Logs not written to elasticsearch

arsen.ferizovic · September 29, 2021, 9:09am

Hello,
On premise setup, Orchestrator 2020.10.8
Elastic v 7.10.1
UiPath.Orchestrator.dll.config is correctly set.

Logs not written to elastic, and ideas where to look further and how to solve this issue.

Many thanks,
Arsen

codemonkee · September 29, 2021, 5:38pm

You’ll have to give more specifics on your setup, what does your configuration look like? Are there any errors being generated?

The first place I would look is

Event Viewer for errors
UiPath.Orchestrator.dll.config, specifically the NLog Targets and Rules sections.
Firewall/Network if Elasticsearch and Orchestrator are not on the same host

arsen.ferizovic · September 29, 2021, 8:06pm

Thanks Tim for your response.

No errors in event viewer.

We already have ELK on separate host, during orchestrator setup, I did not select elastic.

I can write to elastic with CURL command from Orchestrator host.

Logs are written to SQL, but nothing in Elastic.

Config:

 <target xsi:type="ElasticSearch" name="robotElastic" uri="http://XXX:9200" requireAuth="true" username="XXX" password="XXX" index="${event-properties:item=indexName}-${date:format=yyyy.MM}" documentType="logEvent" includeAllProperties="true" disablePing="true"  layout="${message}" excludedProperties="agentSessionId,tenantId,organizationUnitId,indexName"


    <rules>
      <logger name="Robot.*" writeTo="database,robotElasticBuffer" final="true" />
      <logger name="Robot.*" ruleName="insightsRobotLogsRule" enabled="false" minlevel="Info" writeTo="insightsRobotLogs">
        <filters defaultAction="Ignore">
          <when condition="level &gt;= LogLevel.Error or ends-with('${message}',' execution ended')" action="Log" />
        </filters>
      </logger>
      <logger name="BusinessException.*" minlevel="Info" writeTo="businessExceptionEventLog" final="true" />
      <logger name="Monitoring.*" writeTo="monitoring" minlevel="Warn" final="true" />
      <logger name="Quartz.*" minlevel="Warn" writeTo="eventLogQuartz" final="true" />
      <logger name="*" minlevel="Info" writeTo="eventLog" />
    </rules>

codemonkee · September 29, 2021, 8:24pm

In the above you provided

 <target xsi:type="ElasticSearch" name="robotElastic" ... />

Is the provided target node wrapped in another target to match the writeTo in your Robot.* logger?

    <targets>
      ...
      <target name="robotElasticBuffer" xsi:type="BufferingWrapper" flushTimeout="5000">
        <target xsi:type="ElasticSearch" name="robotElastic" ... />
      </target>
      <target name="serverElasticBuffer" xsi:type="BufferingWrapper" flushTimeout="5000">
        <target xsi:type="ElasticSearch" name="serverElastic" ... />
      </target>
      ...
    </targets>
    <rules>
      ...
      <logger name="Robot.*" final="true" writeTo="database,robotElasticBuffer" />
      ...
    </rules>

Short of that… may be worthwhile to enable the internal NLog logging and adjust internalLogLevel and internalLogFile as needed.

<nlog ... autoReload="true" throwExceptions="false" internalLogLevel="Off" internalLogFile="">

arsen.ferizovic · September 30, 2021, 10:30am

Nlog logging enabled. Level Trace.

I dont see any errors, or even, Orchestrator is trying to write to Elastic.
When I run robot I can see logs written to SQL.

2021-09-30 12:24:07.9773 Debug Targets for Robot.tenantId:1.UiPath.Orchestrator.Application.Services.Logs.LogsWriter by level:
2021-09-30 12:24:07.9773 Debug Trace => database robotElasticBuffer serverElasticBuffer
2021-09-30 12:24:07.9864 Debug Debug => database robotElasticBuffer serverElasticBuffer
2021-09-30 12:24:07.9864 Debug Info => database robotElasticBuffer serverElasticBuffer
2021-09-30 12:24:07.9864 Debug Warn => database robotElasticBuffer serverElasticBuffer
2021-09-30 12:24:07.9864 Debug Error => database robotElasticBuffer serverElasticBuffer
2021-09-30 12:24:07.9864 Debug Fatal => database robotElasticBuffer serverElasticBuffer
2021-09-30 12:24:07.9864 Trace AsyncWrapper(Name=database_wrapped): Throttled timer scheduled
2021-09-30 12:24:07.9985 Trace AsyncWrapper(Name=database_wrapped): Writing 1 events (Timer)
2021-09-30 12:24:07.9985 Trace DatabaseTarget(Name=): Executing Text: 
            INSERT INTO dbo.Logs (OrganizationUnitId, TenantId, TimeStamp, Level, WindowsIdentity, ProcessName, JobKey, Message, RawMessage, RobotName, MachineId, UserKey, HostMachineName)
            VALUES (@organizationUnitId, @tenantId, @timeStamp, @level, @windowsIdentity, @processName, @jobId, @message, @rawMessage, @robotName, @machineId, @userKey, @hostMachineName)
          
2021-09-30 12:24:07.9985 Trace   DatabaseTarget: Parameter: '@organizationUnitId' = '6' (String)
2021-09-30 12:24:07.9985 Trace   DatabaseTarget: Parameter: '@tenantId' = '1' (String)
2021-09-30 12:24:07.9985 Trace   DatabaseTarget: Parameter: '@timeStamp' = '2021-09-30 10:24:07.767' (String)
2021-09-30 12:24:07.9985 Trace   DatabaseTarget: Parameter: '@level' = '2' (String)
2021-09-30 12:24:07.9985 Trace   DatabaseTarget: Parameter: '@windowsIdentity' = 'XXX' (String)
2021-09-30 12:24:07.9985 Trace   DatabaseTarget: Parameter: '@processName' = 'HelloWorldXXX' (String)
2021-09-30 12:24:07.9985 Trace   DatabaseTarget: Parameter: '@jobId' = '9edc14b4-9925-46bb-910d-eb7bd882fa1c' (String)
2021-09-30 12:24:07.9985 Trace   DatabaseTarget: Parameter: '@message' = 'HelloWorldXXX execution started' (String)
2021-09-30 12:24:08.0155 Trace   DatabaseTarget: Parameter: '@rawMessage' = '{"message":"HelloWorldDemoXXX execution started","level":"Information","logType":"Default","timeStamp":"2021-09-30T12:24:07.7674758+02:00","fingerprint":"8ad90155-59c0-494c-8d08-e41902a396fc","windowsIdentity":"XXX","machineName":"XXX","processName":"HelloWorldDemoXXX","processVersion":"1.0.4","jobId":"9edc14b4-9925-46bb-910d-eb7bd882fa1c","robotName":"admin-attended","machineId":10,"organizationUnitId":6,"fileName":"Main","initiatedBy":"Studio"}' (String)
2021-09-30 12:24:08.0155 Trace   DatabaseTarget: Parameter: '@robotName' = 'admin-attended' (String)
2021-09-30 12:24:08.0155 Trace   DatabaseTarget: Parameter: '@machineId' = '10' (String)
2021-09-30 12:24:08.0155 Trace   DatabaseTarget: Parameter: '@userKey' = 'c9f640a1-033d-4485-b8c5-3202d0b038bf' (String)
2021-09-30 12:24:08.0155 Trace   DatabaseTarget: Parameter: '@hostMachineName' = 'XXX' (String)
2021-09-30 12:24:08.0309 Trace DatabaseTarget(Name=): Finished execution, result = 1
2021-09-30 12:24:08.6725 Trace AsyncWrapper(Name=database_wrapped): Throttled timer scheduled
2021-09-30 12:24:08.6966 Trace AsyncWrapper(Name=database_wrapped): Writing 2 events (Timer)

codemonkee · October 1, 2021, 12:20am

So I went through the motions

Installed Elasticsearch 7.15 using the MSI

Verified I could read from Elasticsearch using http://<host>:9200/_cat/indices

green  open .geoip_databases                55tEFzXPQqKyYCNCmAFCIA 1 0 43  0 41.1mb 41.1mb

Updated UiPath.Orchestrator.dll.config Target and logger

<nlog ... internalLogLevel="Trace" internalLogFile="C:\temp\NLogOutput.log">
 <targets>
   ...
   <target name="robotElasticBuffer" xsi:type="BufferingWrapper" flushTimeout="5000">
     <target xsi:type="ElasticSearch" 
 	  name="robotElastic" 
 	  uri="http://<host>:9200" 
 	  requireAuth="false" 
 	  username="" 
 	  password="" 
 	  index="${event-properties:item=indexName}-${date:format=yyyy.MM}" 
 	  documentType="logEvent" 
 	  includeAllProperties="true" 
 	  layout="${message}" 
 	  excludedProperties="agentSessionId,tenantId,indexName" 
 	/>
   </target>
 </targets>
 <rules>
   ...
   <logger name="Robot.*" final="true" writeTo="database,robotElasticBuffer" />
   ...
 </rules>

Restarted IIS-Site
Ran Process from Robot Assistant

Verified that I see references in the NLogOutput.log for robotElasticBuffer

2021-09-30 17:44:25.3326 Trace Scanning LoggingRule 'logNamePattern: (Robot.:StartsWith) levels: [ Trace Debug Info Warn Error Fatal ] appendTo: [ database robotElasticBuffer ]'
2021-09-30 17:44:25.6921 Trace BufferingWrapper Target[robotElasticBuffer_wrapped](ElasticSearch Target[robotElastic]) has 3 layouts
2021-09-30 17:44:25.6921 Trace BufferingWrapper(Name=robotElasticBuffer_wrapped): Create Timer
2021-09-30 17:44:25.6921 Trace Initializing UiPrettyExceptionWrapper Target[robotElasticBuffer](BufferingWrapper Target[robotElasticBuffer_wrapped](ElasticSearch Target[robotElastic]))
2021-09-30 17:44:25.6921 Trace FindReachableObject<NLog.Layouts.Layout>:
2021-09-30 17:44:25.6921 Trace Scanning UiPrettyExceptionTarget 'UiPrettyExceptionWrapper Target[robotElasticBuffer](BufferingWrapper Target[robotElasticBuffer_wrapped](ElasticSearch Target[robotElastic]))'
2021-09-30 17:44:25.6921 Trace  Scanning Property WrappedTarget 'BufferingWrapper Target[robotElasticBuffer_wrapped](ElasticSearch Target[robotElastic])' NLog.Targets
2021-09-30 17:44:25.6921 Trace  Scanning BufferingTargetWrapper 'BufferingWrapper Target[robotElasticBuffer_wrapped](ElasticSearch Target[robotElastic])'
2021-09-30 17:44:25.6921 Trace   Scanning Property WrappedTarget 'ElasticSearch Target[robotElastic]' NLog.Targets
2021-09-30 17:44:25.6921 Trace   Scanning ElasticSearchTarget 'ElasticSearch Target[robotElastic]'
2021-09-30 17:44:25.6921 Trace    Scanning Property Index ''${event-properties:item=indexName}-${date:format=yyyy.MM}'' NLog.Layouts
2021-09-30 17:44:25.6921 Trace    Scanning SimpleLayout ''${event-properties:item=indexName}-${date:format=yyyy.MM}''
2021-09-30 17:44:25.6921 Trace    Scanning Property DocumentType ''logEvent'' NLog.Layouts
2021-09-30 17:44:25.6921 Trace    Scanning SimpleLayout ''logEvent''
2021-09-30 17:44:25.6921 Trace    Scanning Property Layout ''${message}'' NLog.Layouts
2021-09-30 17:44:25.6921 Trace    Scanning SimpleLayout ''${message}''
2021-09-30 17:44:25.6921 Trace    Scanning Property Fields 'System.Collections.Generic.List`1[NLog.Targets.ElasticSearch.Field]' System.Collections.Generic
2021-09-30 17:44:25.6921 Trace UiPrettyExceptionWrapper Target[robotElasticBuffer](BufferingWrapper Target[robotElasticBuffer_wrapped](ElasticSearch Target[robotElastic])) has 3 layouts
2021-09-30 17:44:25.6921 Trace UiPrettyExceptionWrapper Target[robotElasticBuffer](BufferingWrapper Target[robotElasticBuffer_wrapped](ElasticSearch Target[robotElastic])) has 3 layouts
2021-09-30 17:45:56.8000 Debug Trace => database robotElasticBuffer
2021-09-30 17:45:56.8000 Debug Debug => database robotElasticBuffer
2021-09-30 17:45:56.8000 Debug Info => insightsRobotLogs (1 filters) database robotElasticBuffer
2021-09-30 17:45:56.8000 Debug Warn => insightsRobotLogs (1 filters) database robotElasticBuffer
2021-09-30 17:45:56.8000 Debug Error => insightsRobotLogs (1 filters) database robotElasticBuffer
2021-09-30 17:45:56.8000 Debug Fatal => insightsRobotLogs (1 filters) database robotElasticBuffer

Checked Indices again http://<host>:9200/_cat/indices

green  open .geoip_databases                55tEFzXPQqKyYCNCmAFCIA 1 0 43   0  41.1mb  41.1mb
green  open .kibana_7.15.0_001              Nr5u83zHRKCGC-8BT_mxDw 1 0 23   6   4.7mb   4.7mb
green  open .apm-custom-link                opGjbXwsQFeCKeI_SacyrQ 1 0  0   0    208b    208b
yellow open default-2021.09                 5fC1jT4vRw-YPWfcI6FOAA 1 1  2   0    33kb    33kb
green  open .kibana-event-log-7.15.0-000001 g2fl2EcCT26jqbPpfDMFsA 1 0  2   0  11.9kb  11.9kb
green  open .apm-agent-configuration        dn3_c_j1TNK5TlndUBxHVQ 1 0  0   0    208b    208b
green  open .kibana_task_manager_7.15.0_001 VLk3tHM8QpOyA-kvSpeh3g 1 0 15 330 194.8kb 194.8kb
green  open .tasks                          cXxeXxJ-QWC5xf-f6-zQCQ 1 0  2   0  13.7kb  13.7kb

The default-2021.09 is what I am expecting to see based on the index attribute set in the target configuraton

Simple search of the index http://<host>:9200/default-2021.09/_search and I see the expected message events matching what flow into the database and Splunk. (Truncated for brevity)

{
  "took": 5,
  "timed_out": false,
  "_shards": {
    "total": 1,
    "successful": 1,
    "skipped": 0,
    "failed": 0
  },
  "hits": {
    "total": {
      "value": 2,
      "relation": "eq"
    },
    "max_score": 1.0,
    "hits": [
      {
        "_index": "default-2021.09",
        "_type": "logEvent",
        "_id": "-1cZOXwBH67HVO-4xqNx",
        "_score": 1.0,
        "_ignored": [
          "rawMessage.keyword"
        ],
        "_source": {
          "@timestamp": "2021-09-30T23:45:55.7459193Z",
          "level": "Info",
          "message": "TestRandomFault_Default execution started",
          "levelOrdinal": 2,
          "timeStamp": "2021-09-30T23:45:55.7459193Z",
          "Source": "Robot",
          "organizationUnitId": 1,
          "logType": "Default",
          "fingerprint": "77b2eea4-00ac-4cdb-867e-c4e825d1a925",
          "windowsIdentity": "username",
          "machineName": "machinename",
          "processName": "TestRandomFault_Default",
          "processVersion": "1.0.1-alpha.4",
          "jobId": "10d33a79-8562-463c-b01c-fe1bf43f4e0c",
          "robotName": "Tim",
          "machineId": 81,
          "fileName": "Main",
          "initiatedBy": "Assistant",
...

The only difference that I can see is

I haven’t set it up for authentication
you have excluded organizationUnitId from the properties list. Which I can’t think of why that would matter.

The only thing I can think of is to

doublecheck your Target robotElastic is also wrapped up in a Target robotElasticBuffer - Try without auth if you can to help narrow done where to troubleshoot.

arsen.ferizovic · October 5, 2021, 8:17am

Tim, thanks for all your help.

Now it is working, still not 100% where was the issue.
Only difference is, new index was created “default-2021.10” logs are written.
in “default-2021.09” no logs.

Regards,
Arsen

BrandonPaul · January 25, 2022, 6:30pm

We had a similar issue, but we were also writing Robot.* logs to Windows event log, and to solve our issue, we had to set final=“false” for the logger that was writing to robotElasticBuffer. Once we did that, it started successfully writing to the SQL database as well as to Elasticsearch.

<logger name="Robot.*" final="false" writeTo="robotElasticBuffer,database" ruleName="primaryRobotLogsTarget" />
<logger name="Robot.*" ruleName="primaryRobotLogsTarget" minlevel="Warn" final="true" writeTo="eventlog" />

codemonkee · January 25, 2022, 7:10pm

Alternatively, assuming your other attributes / requirements are similar, you could include your eventlog targetname in the writeTo attribute of the first logger and drop the second one.

system · January 28, 2022, 7:11pm

This topic was automatically closed 3 days after the last reply. New replies are no longer allowed.

Most Active Users - Yesterday
Anil_G
Yoichi
Chirag_Shetty_Divakar
supermanPunch
ushu
Pavanraj_Shetty
Manish540
arjunshenoy
Jithesh_R
JenJen
More details...