Bug 1458735 - Logs in engine.log that contain javastacktrace break log parsing
Summary: Logs in engine.log that contain javastacktrace break log parsing
Keywords:
Status: CLOSED CURRENTRELEASE
Alias: None
Product: ovirt-engine-metrics
Classification: oVirt
Component: Generic
Version: 1.0.4.2
Hardware: Unspecified
OS: Unspecified
high
medium
Target Milestone: ovirt-4.1.3
: 1.0.4.3
Assignee: Shirly Radco
QA Contact: Lukas Svaty
URL:
Whiteboard:
Depends On: 1464394
Blocks: oVirt-Metrics-and-Logs 1456459
TreeView+ depends on / blocked
 
Reported: 2017-06-05 11:12 UTC by Shirly Radco
Modified: 2017-07-06 13:11 UTC (History)
5 users (show)

Fixed In Version:
Doc Type: If docs needed, set a value
Doc Text:
Clone Of:
Environment:
Last Closed: 2017-07-06 13:11:55 UTC
oVirt Team: Metrics
Embargoed:
rule-engine: ovirt-4.1+
lsvaty: testing_ack+


Attachments (Terms of Use)


Links
System ID Private Priority Status Summary Last Updated
oVirt gerrit 78280 0 master MERGED fluebtd: update engine logs format to support multiline 2017-06-18 19:05:58 UTC

Description Shirly Radco 2017-06-05 11:12:57 UTC
Description of problem:
Logs in engine.log that contain javastacktrace break log parsing.
Common logging recommend to output Java stacktraces in single line JSON format.

Version-Release number of selected component (if applicable):
1.0.3

How reproducible:


Steps to Reproduce:
1.
2.
3.

Actual results:


Expected results:


Additional info:

Comment 1 Martin Perina 2017-06-06 10:48:07 UTC
This most probably won't be fixed ever, for some critical exceptions we just need stacktrace in INFO, you need to by pass that inside common logging (for example adding whole line to previous message if line doesn't start with "<TIMESTAMP> <LOG LEVEL>"

Comment 2 Shirly Radco 2017-06-18 19:08:12 UTC
I updated the fluentd to be able to consume multiline log messages.

Comment 3 Lukas Svaty 2017-06-22 09:53:40 UTC
ovirt-engine-metrics-1.0.4.2-1.el7ev.noarch

At the moment we throw away the traceback and just logs the error, as mentioned by Martin for components such as mom it is vital to store the traceback to be able to debug issues properly.


See event stored:
EVENT_ID: VDS_FAILURE(12), Correlation ID: null, Call Stack: org.ovirt.engine.core.vdsbroker.vdsbroker.VDSNetworkException: java.rmi.ConnectException: Connection timeout

No traceback afterwards in the logged sample, next log message continues

Comment 4 Red Hat Bugzilla Rules Engine 2017-06-22 09:53:44 UTC
Target release should be placed once a package build is known to fix a issue. Since this bug is not modified, the target version has been reset. Please use target milestone to plan a fix for a oVirt release.

Comment 5 Shirly Radco 2017-06-22 11:07:11 UTC
I fixed this in fluentd config, please test.

Comment 6 Lukas Svaty 2017-06-22 11:11:47 UTC
waiting for new build

Comment 7 Lukas Svaty 2017-06-26 13:50:13 UTC
Tracebacks available in ovirt-engine-metrics-1.0.4.3-1.el7ev.noarch


{
  "_index": "ovirt-metrics-2017.06.26",
  "_type": "fluentd",
  "_id": "AVzkoJrcGiB38QjWeuEp",
  "_score": null,
  "_source": {
    "level": "ERROR",
    "message": "EVENT_ID: VDS_FAILURE(12), Correlation ID: null, Call Stack: org.ovirt.engine.core.vdsbroker.vdsbroker.VDSNetworkException: java.rmi.ConnectException: Connection timeout\n\tat org.ovirt.engine.core.vdsbroker.vdsbroker.VdsBrokerCommand.createNetworkException(VdsBrokerCommand.java:158)\n\tat org.ovirt.engine.core.vdsbroker.vdsbroker.VdsBrokerCommand.executeVDSCommand(VdsBrokerCommand.java:121)\n\tat org.ovirt.engine.core.vdsbroker.VDSCommandBase.executeCommand(VDSCommandBase.java:73)\n\tat org.ovirt.engine.core.dal.VdcCommandBase.execute(VdcCommandBase.java:33)\n\tat org.ovirt.engine.core.vdsbroker.vdsbroker.DefaultVdsCommandExecutor.execute(DefaultVdsCommandExecutor.java:14)\n\tat org.ovirt.engine.core.vdsbroker.ResourceManager.runVdsCommand(ResourceManager.java:408)\n\tat org.ovirt.engine.core.vdsbroker.VdsManager.refreshCapabilities(VdsManager.java:677)\n\tat org.ovirt.engine.core.vdsbroker.monitoring.HostMonitoring.refreshVdsRunTimeInfo(HostMonitoring.java:117)\n\tat org.ovirt.engine.core.vdsbroker.monitoring.HostMonitoring.refresh(HostMonitoring.java:84)\n\tat org.ovirt.engine.core.vdsbroker.VdsManager.onTimer(VdsManager.java:275)\n\tat sun.reflect.GeneratedMethodAccessor80.invoke(Unknown Source)\n\tat sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)\n\tat java.lang.reflect.Method.invoke(Method.java:498)\n\tat org.ovirt.engine.core.utils.timer.JobWrapper.invokeMethod(JobWrapper.java:83)\n\tat org.ovirt.engine.core.utils.timer.JobWrapper.execute(JobWrapper.java:55)\n\tat org.quartz.core.JobRunShell.run(JobRunShell.java:213)\n\tat java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)\n\tat java.util.concurrent.FutureTask.run(FutureTask.java:266)\n\tat java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)\n\tat java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)\n\tat java.lang.Thread.run(Thread.java:748)\nCaused by: java.rmi.ConnectException: Connection timeout\n\tat org.ovirt.vdsm.jsonrpc.client.reactors.ReactorClient.lambda$connect$1(ReactorClient.java:120)\n\tat org.ovirt.vdsm.jsonrpc.client.utils.retry.Retryable.call(Retryable.java:27)\n\tat java.util.concurrent.FutureTask.run(FutureTask.java:266)\n\tat org.ovirt.vdsm.jsonrpc.client.utils.ReactorScheduler.performPendingOperations(ReactorScheduler.java:25)\n\tat org.ovirt.vdsm.jsonrpc.client.reactors.Reactor.run(Reactor.java:61)\n, Custom Event ID: -1, Message: Host moonmoon is non responsive.",
    "service": "ovirt.engine",
    "tag": "project.ovirt-logs-engine",
    "hostname": "ls-engine1.example.com",
    "ovirt": {
      "class": "org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector",
      "thread": "org.ovirt.thread.pool-7-thread-1",
      "correlationid": "75bf338b"
    },
    "@timestamp": "2017-06-26T15:38:12+02:00"
  },
  "fields": {
    "@timestamp": [
      1498484292000
    ]
  },
  "highlight": {
    "message": [
      "EVENT_ID: VDS_FAILURE(12), Correlation ID: null, Call Stack: org.ovirt.engine.core.vdsbroker.vdsbroker.VDSNetworkException: @kibana-highlighted-field.ConnectException@/kibana-highlighted-field@: Connection timeout\n\tat org.ovirt.engine.core.vdsbroker.vdsbroker.VdsBrokerCommand.createNetworkException(VdsBrokerCommand.java:158)\n\tat org.ovirt.engine.core.vdsbroker.vdsbroker.VdsBrokerCommand.executeVDSCommand(VdsBrokerCommand.java:121)\n\tat org.ovirt.engine.core.vdsbroker.VDSCommandBase.executeCommand(VDSCommandBase.java:73)\n\tat org.ovirt.engine.core.dal.VdcCommandBase.execute(VdcCommandBase.java:33)\n\tat org.ovirt.engine.core.vdsbroker.vdsbroker.DefaultVdsCommandExecutor.execute(DefaultVdsCommandExecutor.java:14)\n\tat org.ovirt.engine.core.vdsbroker.ResourceManager.runVdsCommand(ResourceManager.java:408)\n\tat org.ovirt.engine.core.vdsbroker.VdsManager.refreshCapabilities(VdsManager.java:677)\n\tat org.ovirt.engine.core.vdsbroker.monitoring.HostMonitoring.refreshVdsRunTimeInfo(HostMonitoring.java:117)\n\tat org.ovirt.engine.core.vdsbroker.monitoring.HostMonitoring.refresh(HostMonitoring.java:84)\n\tat org.ovirt.engine.core.vdsbroker.VdsManager.onTimer(VdsManager.java:275)\n\tat sun.reflect.GeneratedMethodAccessor80.invoke(Unknown Source)\n\tat sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)\n\tat java.lang.reflect.Method.invoke(Method.java:498)\n\tat org.ovirt.engine.core.utils.timer.JobWrapper.invokeMethod(JobWrapper.java:83)\n\tat org.ovirt.engine.core.utils.timer.JobWrapper.execute(JobWrapper.java:55)\n\tat org.quartz.core.JobRunShell.run(JobRunShell.java:213)\n\tat java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)\n\tat java.util.concurrent.FutureTask.run(FutureTask.java:266)\n\tat java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)\n\tat java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)\n\tat java.lang.Thread.run(Thread.java:748)\nCaused by: @kibana-highlighted-field.ConnectException@/kibana-highlighted-field@: Connection timeout\n\tat org.ovirt.vdsm.jsonrpc.client.reactors.ReactorClient.lambda$connect$1(ReactorClient.java:120)\n\tat org.ovirt.vdsm.jsonrpc.client.utils.retry.Retryable.call(Retryable.java:27)\n\tat java.util.concurrent.FutureTask.run(FutureTask.java:266)\n\tat org.ovirt.vdsm.jsonrpc.client.utils.ReactorScheduler.performPendingOperations(ReactorScheduler.java:25)\n\tat org.ovirt.vdsm.jsonrpc.client.reactors.Reactor.run(Reactor.java:61)\n, Custom Event ID: -1, Message: Host moonmoon is non responsive."
    ]
  },
  "sort": [
    1498484292000
  ]
}


Note You need to log in before you can comment on or make changes to this bug.