search

vectordotdev / vector

A high-performance observability data pipeline.
https://vector.dev
Mozilla Public License 2.0
17.04k stars 1.47k forks source link

File source ignored when started from systemd #20268

Closed tino closed 1 month ago

tino commented 3 months ago

A note for the community

Problem

When started with sudo vector it works and my logs are processed. When starting with the same config file, but with sudo systemctl start vector there is no output, not in the console, and on top everything stays at N/A.

In both cases I waited long enough and checked that there was actually stuff added to the log file.

Configuration

# /etc/vector/vector.yaml
api:
  enabled: true

sources:
  service_logs:
    type: file
    include:
      - /path/to/logs/service1.log

transforms:
  service_logs_fmted:
    type: remap
    inputs: ['service_logs']
    drop_on_abort: false
    drop_on_error: false
    source: |
      message = parse_logfmt!(.message)
      .file = .file
      .logger = message.logger
      .level = message.level
      .timestamp = parse_timestamp!(message.timestamp, format: "%Y-%m-%d %H:%M:%S")
      .msg = message.event

sinks:
  console:
    type: console
    inputs:
      - service_logs_fmted
    encoding:
      codec: logfmt

  service_to_loki:
    type: loki
    inputs:
      - service_logs_fmted
    # compression: snappy
    endpoint: http://localhost:3100
    encoding:
      codec: json
    out_of_order_action: accept
    # remove_timestamp: true
    tenant_id: s1
    labels:
      'host': '{{ host }}'
      'level': '{{ level }}'
      'file': '{{ file }}'
      'logger': '{{ logger }}'

Version

vector 0.36.1 (x86_64-unknown-linux-gnu 2857180 2024-03-11 14:32:52.417737479)

Debug Output

Logs from `sudo vector`:

2024-04-09T20:15:51.941883Z  INFO vector::app: Log level is enabled. level="info"
2024-04-09T20:15:51.950407Z  INFO vector::app: Loading configs. paths=["/etc/vector/vector.yaml"]
2024-04-09T20:15:51.978207Z  INFO vector::topology::running: Running healthchecks.
2024-04-09T20:15:51.978328Z  INFO vector: Vector has started. debug="false" version="0.36.1" arch="x86_64" revision="2857180 2024-03-11 14:32:52.417737479"
2024-04-09T20:15:51.978342Z  INFO source{component_kind="source" component_id=service_logs component_type=file}: vector::sources::file: Starting file server. include=["/home/tino/projects/homeserver/logs/home.log"] exclude=[]
2024-04-09T20:15:51.980136Z  INFO vector::topology::builder: Healthcheck passed.
2024-04-09T20:15:51.981634Z  INFO source{component_kind="source" component_id=service_logs component_type=file}:file_server: file_source::checkpointer: Loaded checkpoint data.
2024-04-09T20:15:51.981929Z  INFO source{component_kind="source" component_id=service_logs component_type=file}:file_server: vector::internal_events::file::source: Resuming to watch file. file=/home/tino/projects/homeserver/logs/home.log file_position=1511039
2024-04-09T20:15:51.982133Z  INFO vector::internal_events::api: API server running. address=127.0.0.1:8686 playground=http://127.0.0.1:8686/playground graphql=http://127.0.0.1:8686/graphql
2024-04-09T20:15:51.983085Z  INFO vector::topology::builder: Healthcheck passed.
file=/path/to/logs/service1.log host=s1 level=info logger=home.to_db_otgw message="event=\"Inserted 38 rows\" level=info logger=home.to_db_otgw timestamp=\"2024-04-09 22:15:24\"" msg="Inserted 38 rows" source_type=file timestamp=2024-04-09T20:15:24Z
file=/path/to/logs/service1.log host=s1 level=info logger=home.to_db_otgw message="event=\"Inserted 29 rows\" level=info logger=home.to_db_otgw timestamp=\"2024-04-09 22:15:29\"" msg="Inserted 29 rows" source_type=file timestamp=2024-04-09T20:15:29Z
...

The last 2 lines are the ones I want to see.

From journalctl, when started with sudo systemctl start vector:

Apr 09 22:17:44 s1 systemd[1]: Started vector.service - Vector.
Apr 09 22:17:44 s1 vector[88710]: 2024-04-09T20:17:44.745667Z  INFO vector::app: Log level is enabled. level="info"
Apr 09 22:17:44 s1 vector[88710]: 2024-04-09T20:17:44.751304Z  INFO vector::app: Loading configs. paths=["/etc/vector/vector.yaml"]
Apr 09 22:17:44 s1 vector[88710]: 2024-04-09T20:17:44.780874Z  INFO vector::topology::running: Running healthchecks.
Apr 09 22:17:44 s1 vector[88710]: 2024-04-09T20:17:44.780973Z  INFO vector: Vector has started. debug="false" version="0.36.1" arch="x86_64" revision="2857180 2024-03-11 14:32:52.417737479"
Apr 09 22:17:44 s1 vector[88710]: 2024-04-09T20:17:44.781183Z  INFO vector::topology::builder: Healthcheck passed.
Apr 09 22:17:44 s1 vector[88710]: 2024-04-09T20:17:44.781317Z  INFO source{component_kind="source" component_id=service_logs component_type=file}: vector::sources::file: Starting file server. include=["/path/to/logs/service1.log"] exclude=[]
Apr 09 22:17:44 s1 vector[88710]: 2024-04-09T20:17:44.781963Z  INFO source{component_kind="source" component_id=service_logs component_type=file}:file_server: file_source::checkpointer: Loaded checkpoint data.
Apr 09 22:17:44 s1 vector[88710]: 2024-04-09T20:17:44.782292Z  INFO vector::internal_events::api: API server running. address=127.0.0.1:8686 playground=http://127.0.0.1:8686/playground graphql=http://127.0.0.1:8686/graphql
Apr 09 22:17:44 s1 vector[88710]: 2024-04-09T20:17:44.783294Z  INFO vector::topology::builder: Healthcheck passed.

<nothing more!>


### Example Data

_No response_

### Additional Context

_No response_

### References

_No response_
jszwedko commented 3 months ago

Hi @tino ,

Did you check JournalD to see if the output is there? I think the difference is that the console sink writes to stdout but Vector's internal logs go to stderr. Both should end up in JournalD by default though. See https://www.freedesktop.org/software/systemd/man/latest/systemd.exec.html#StandardOutput=

tino commented 2 months ago

Yes I did. As I showed in my initial post, those are the logs from JournalD (sudo journalctl -fu vector).

And I also don't see these in Loki.

tino commented 2 months ago

OK I found the difference. When I start as systemd job, vector runs under the vector user. However vector does have access to the file I want it to read, with world group permission. 

ls -alh /path/to/logs/service1.log
-rw-r-xr--+ 1 tino tino 2.9M May 12 21:20 /path/to/logs/service1.log

And I even tried with with setfacl:

$ getfacl /path/to/logs/service1.log
getfacl: Removing leading '/' from absolute path names
# file: path/to/logs/service1.log
# owner: tino
# group: tino
user::rw-
user:vector:r-x
group::r--
mask::r-x
other::r--

So why wouldn't that work? Does it need write access too?

jszwedko commented 1 month ago

OK I found the difference. When I start as systemd job, vector runs under the vector user. However vector does have access to the file I want it to read, with world group permission.

ls -alh /path/to/logs/service1.log
-rw-r-xr--+ 1 tino tino 2.9M May 12 21:20 /path/to/logs/service1.log

And I even tried with with setfacl:

$ getfacl /path/to/logs/service1.log
getfacl: Removing leading '/' from absolute path names
# file: path/to/logs/service1.log
# owner: tino
# group: tino
user::rw-
user:vector:r-x
group::r--
mask::r-x
other::r--

So why wouldn't that work? Does it need write access too?

I would check all parent directories too to make sure it has access. You could run sudo -u vector head <full path> to check if the vector user can read the file.

jszwedko commented 1 month ago

Closing as stale, but let me know if you are still having issues!