Skip to content

Conversation

@blizzz
Copy link
Member

@blizzz blizzz commented Jan 15, 2020

  • Extends ILogger to log custom data
  • Logs flow activiation by event hooks (i.e. complex operators that have own listeners like Autotagging and accesscontrol are below radar)
  • Logs rule fetching and evaluation (any Operation is caught here)
  • Logs to $datadir/flow.log by default (can be disabled via cli, or a different location specified)
  • No flow app has to do anything itself
  • Rotates according to general rotation logic

Example content:

{"reqId":"X5XP4vROpcGCoaE6Ria2","level":1,"time":"2020-01-15T09:32:29+00:00","remoteAddr":"127.0.0.1","user":"master","app":"workflowengine","method":"GET","url":"/master/ocs/v2.php/apps/flow_http_requests/api/v1/f/m7b43vgb?action=ping","message":{"operation":{"class":"OCA\\Talk\\Flow\\Operation","name":"Write to conversation"},"entity":{"class":"OCA\\FlowHttpRequests\\Flow\\RequestEntity","name":"Web Request"},"eventName":"FlowHttpRequest::incomingRequest","description":"Flow activated by event"},"userAgent":"curl/7.68.0","version":"18.0.0.8"}
{"reqId":"X5XP4vROpcGCoaE6Ria2","level":1,"time":"2020-01-15T09:32:29+00:00","remoteAddr":"127.0.0.1","user":"master","app":"workflowengine","method":"GET","url":"/master/ocs/v2.php/apps/flow_http_requests/api/v1/f/m7b43vgb?action=ping","message":{"scopes":[{"scope":"admin"},{"scope":"user","uid":"master"}],"entity":{"class":"OCA\\FlowHttpRequests\\Flow\\RequestEntity","name":"Web Request"},"operation":{"class":"OCA\\Talk\\Flow\\Operation","name":"Write to conversation"},"description":"Flow activation: rules were requested"},"userAgent":"curl/7.68.0","version":"18.0.0.8"}
{"reqId":"X5XP4vROpcGCoaE6Ria2","level":1,"time":"2020-01-15T09:32:29+00:00","remoteAddr":"127.0.0.1","user":"master","app":"workflowengine","method":"GET","url":"/master/ocs/v2.php/apps/flow_http_requests/api/v1/f/m7b43vgb?action=ping","message":{"entity":{"class":"OCA\\FlowHttpRequests\\Flow\\RequestEntity","name":"Web Request"},"operation":{"class":"OCA\\Talk\\Flow\\Operation","name":"Write to conversation"},"configuration":{"id":60,"class":"OCA\\Talk\\Flow\\Operation","name":"","checks":"[81]","operation":"{\"m\":3,\"t\":\"wfwqkvsc\"}","events":"[\"FlowHttpRequest::incomingRequest\"]","entity":"OCA\\FlowHttpRequests\\Flow\\RequestEntity","scope_type":1,"scope_actor_id":"master"},"description":"Flow rule qualified to run"},"userAgent":"curl/7.68.0","version":"18.0.0.8"}
{"reqId":"X5XP4vROpcGCoaE6Ria2","level":1,"time":"2020-01-15T09:32:29+00:00","remoteAddr":"127.0.0.1","user":"master","app":"workflowengine","method":"GET","url":"/master/ocs/v2.php/apps/flow_http_requests/api/v1/f/m7b43vgb?action=ping","message":{"entity":{"class":"OCA\\FlowHttpRequests\\Flow\\RequestEntity","name":"Web Request"},"operation":{"class":"OCA\\Talk\\Flow\\Operation","name":"Write to conversation"},"configuration":[{"id":60,"class":"OCA\\Talk\\Flow\\Operation","name":"","checks":"[81]","operation":"{\"m\":3,\"t\":\"wfwqkvsc\"}","events":"[\"FlowHttpRequest::incomingRequest\"]","entity":"OCA\\FlowHttpRequests\\Flow\\RequestEntity","scope_type":1,"scope_actor_id":"master"}],"description":"All qualified flow configurations are going to run"},"userAgent":"curl/7.68.0","version":"18.0.0.8"}
{"reqId":"X5XP4vROpcGCoaE6Ria2","level":1,"time":"2020-01-15T09:32:29+00:00","remoteAddr":"127.0.0.1","user":"master","app":"workflowengine","method":"GET","url":"/master/ocs/v2.php/apps/flow_http_requests/api/v1/f/m7b43vgb?action=ping","message":{"operation":{"class":"OCA\\Talk\\Flow\\Operation","name":"Write to conversation"},"entity":{"class":"OCA\\FlowHttpRequests\\Flow\\RequestEntity","name":"Web Request"},"eventName":"FlowHttpRequest::incomingRequest","description":"Flow handling for event done"},"userAgent":"curl/7.68.0","version":"18.0.0.8"}
{"reqId":"X5XP4vROpcGCoaE6Ria2","level":1,"time":"2020-01-15T09:32:29+00:00","remoteAddr":"127.0.0.1","user":"master","app":"workflowengine","method":"GET","url":"/master/ocs/v2.php/apps/flow_http_requests/api/v1/f/m7b43vgb?action=ping","message":{"operation":{"class":"OCA\\WorkflowScript\\Operation","name":"External scripts"},"entity":{"class":"OCA\\FlowHttpRequests\\Flow\\RequestEntity","name":"Web Request"},"eventName":"FlowHttpRequest::incomingRequest","description":"Flow activated by event"},"userAgent":"curl/7.68.0","version":"18.0.0.8"}
{"reqId":"X5XP4vROpcGCoaE6Ria2","level":1,"time":"2020-01-15T09:32:29+00:00","remoteAddr":"127.0.0.1","user":"master","app":"workflowengine","method":"GET","url":"/master/ocs/v2.php/apps/flow_http_requests/api/v1/f/m7b43vgb?action=ping","message":{"operation":{"class":"OCA\\WorkflowScript\\Operation","name":"External scripts"},"entity":{"class":"OCA\\FlowHttpRequests\\Flow\\RequestEntity","name":"Web Request"},"eventName":"FlowHttpRequest::incomingRequest","description":"Flow handling for event done"},"userAgent":"curl/7.68.0","version":"18.0.0.8"}
💄 Prettified

cat data/flow.log | jq

{
  "reqId": "X5XP4vROpcGCoaE6Ria2",
  "level": 1,
  "time": "2020-01-15T09:32:29+00:00",
  "remoteAddr": "127.0.0.1",
  "user": "master",
  "app": "workflowengine",
  "method": "GET",
  "url": "/master/ocs/v2.php/apps/flow_http_requests/api/v1/f/m7b43vgb?action=ping",
  "message": {
    "operation": {
      "class": "OCA\\Talk\\Flow\\Operation",
      "name": "Write to conversation"
    },
    "entity": {
      "class": "OCA\\FlowHttpRequests\\Flow\\RequestEntity",
      "name": "Web Request"
    },
    "eventName": "FlowHttpRequest::incomingRequest",
    "description": "Flow activated by event"
  },
  "userAgent": "curl/7.68.0",
  "version": "18.0.0.8"
}
{
  "reqId": "X5XP4vROpcGCoaE6Ria2",
  "level": 1,
  "time": "2020-01-15T09:32:29+00:00",
  "remoteAddr": "127.0.0.1",
  "user": "master",
  "app": "workflowengine",
  "method": "GET",
  "url": "/master/ocs/v2.php/apps/flow_http_requests/api/v1/f/m7b43vgb?action=ping",
  "message": {
    "scopes": [
      {
        "scope": "admin"
      },
      {
        "scope": "user",
        "uid": "master"
      }
    ],
    "entity": {
      "class": "OCA\\FlowHttpRequests\\Flow\\RequestEntity",
      "name": "Web Request"
    },
    "operation": {
      "class": "OCA\\Talk\\Flow\\Operation",
      "name": "Write to conversation"
    },
    "description": "Flow activation: rules were requested"
  },
  "userAgent": "curl/7.68.0",
  "version": "18.0.0.8"
}
{
  "reqId": "X5XP4vROpcGCoaE6Ria2",
  "level": 1,
  "time": "2020-01-15T09:32:29+00:00",
  "remoteAddr": "127.0.0.1",
  "user": "master",
  "app": "workflowengine",
  "method": "GET",
  "url": "/master/ocs/v2.php/apps/flow_http_requests/api/v1/f/m7b43vgb?action=ping",
  "message": {
    "entity": {
      "class": "OCA\\FlowHttpRequests\\Flow\\RequestEntity",
      "name": "Web Request"
    },
    "operation": {
      "class": "OCA\\Talk\\Flow\\Operation",
      "name": "Write to conversation"
    },
    "configuration": {
      "id": 60,
      "class": "OCA\\Talk\\Flow\\Operation",
      "name": "",
      "checks": "[81]",
      "operation": "{\"m\":3,\"t\":\"wfwqkvsc\"}",
      "events": "[\"FlowHttpRequest::incomingRequest\"]",
      "entity": "OCA\\FlowHttpRequests\\Flow\\RequestEntity",
      "scope_type": 1,
      "scope_actor_id": "master"
    },
    "description": "Flow rule qualified to run"
  },
  "userAgent": "curl/7.68.0",
  "version": "18.0.0.8"
}
{
  "reqId": "X5XP4vROpcGCoaE6Ria2",
  "level": 1,
  "time": "2020-01-15T09:32:29+00:00",
  "remoteAddr": "127.0.0.1",
  "user": "master",
  "app": "workflowengine",
  "method": "GET",
  "url": "/master/ocs/v2.php/apps/flow_http_requests/api/v1/f/m7b43vgb?action=ping",
  "message": {
    "entity": {
      "class": "OCA\\FlowHttpRequests\\Flow\\RequestEntity",
      "name": "Web Request"
    },
    "operation": {
      "class": "OCA\\Talk\\Flow\\Operation",
      "name": "Write to conversation"
    },
    "configuration": [
      {
        "id": 60,
        "class": "OCA\\Talk\\Flow\\Operation",
        "name": "",
        "checks": "[81]",
        "operation": "{\"m\":3,\"t\":\"wfwqkvsc\"}",
        "events": "[\"FlowHttpRequest::incomingRequest\"]",
        "entity": "OCA\\FlowHttpRequests\\Flow\\RequestEntity",
        "scope_type": 1,
        "scope_actor_id": "master"
      }
    ],
    "description": "All qualified flow configurations are going to run"
  },
  "userAgent": "curl/7.68.0",
  "version": "18.0.0.8"
}
{
  "reqId": "X5XP4vROpcGCoaE6Ria2",
  "level": 1,
  "time": "2020-01-15T09:32:29+00:00",
  "remoteAddr": "127.0.0.1",
  "user": "master",
  "app": "workflowengine",
  "method": "GET",
  "url": "/master/ocs/v2.php/apps/flow_http_requests/api/v1/f/m7b43vgb?action=ping",
  "message": {
    "operation": {
      "class": "OCA\\Talk\\Flow\\Operation",
      "name": "Write to conversation"
    },
    "entity": {
      "class": "OCA\\FlowHttpRequests\\Flow\\RequestEntity",
      "name": "Web Request"
    },
    "eventName": "FlowHttpRequest::incomingRequest",
    "description": "Flow handling for event done"
  },
  "userAgent": "curl/7.68.0",
  "version": "18.0.0.8"
}
{
  "reqId": "X5XP4vROpcGCoaE6Ria2",
  "level": 1,
  "time": "2020-01-15T09:32:29+00:00",
  "remoteAddr": "127.0.0.1",
  "user": "master",
  "app": "workflowengine",
  "method": "GET",
  "url": "/master/ocs/v2.php/apps/flow_http_requests/api/v1/f/m7b43vgb?action=ping",
  "message": {
    "operation": {
      "class": "OCA\\WorkflowScript\\Operation",
      "name": "External scripts"
    },
    "entity": {
      "class": "OCA\\FlowHttpRequests\\Flow\\RequestEntity",
      "name": "Web Request"
    },
    "eventName": "FlowHttpRequest::incomingRequest",
    "description": "Flow activated by event"
  },
  "userAgent": "curl/7.68.0",
  "version": "18.0.0.8"
}
{
  "reqId": "X5XP4vROpcGCoaE6Ria2",
  "level": 1,
  "time": "2020-01-15T09:32:29+00:00",
  "remoteAddr": "127.0.0.1",
  "user": "master",
  "app": "workflowengine",
  "method": "GET",
  "url": "/master/ocs/v2.php/apps/flow_http_requests/api/v1/f/m7b43vgb?action=ping",
  "message": {
    "operation": {
      "class": "OCA\\WorkflowScript\\Operation",
      "name": "External scripts"
    },
    "entity": {
      "class": "OCA\\FlowHttpRequests\\Flow\\RequestEntity",
      "name": "Web Request"
    },
    "eventName": "FlowHttpRequest::incomingRequest",
    "description": "Flow handling for event done"
  },
  "userAgent": "curl/7.68.0",
  "version": "18.0.0.8"
}

@blizzz blizzz added this to the Nextcloud 19 milestone Jan 15, 2020
@blizzz
Copy link
Member Author

blizzz commented Jan 15, 2020

/backport to stable18

}

public function setOperation(?IOperation $operation): LogContext {
if($operation instanceof IOperation) {
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

given the type hint on the parameter this change is a bit weird. is this a null check?

also, why is the parameter nullable when passing in null doesn't actually do anything? 🤔

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

doesn't bloat the code in RuleMatcher to much, where it is not guaranteed that an operation is set (you can work around with using deprecated API)

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

If nothing is set, log should not crash

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

let me rephrase: did you mean to if ($operation !== null)? Because except for null the $operation will always be of type IOperation as per type hint.

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

yes

}

public function setEntity(?IEntity $entity): LogContext {
if($entity instanceof IEntity) {
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

same here

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

see above

*
* @since 18.0.0
*/
public function logData(array $data, array $context = []): void;
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

should we also add something like a message parameter here? all other logger methods either take a string or an exception that contains a message.

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

imho this should be just part of the data array that is being passed into

@blizzz
Copy link
Member Author

blizzz commented Jan 16, 2020

@ChristophWurst ok?

others – reviews 🌻 ?

@icewind1991
Copy link
Member

If this has a chance of being logged to the main log the the logreader will need to be able to handle it

@blizzz
Copy link
Member Author

blizzz commented Jan 16, 2020

@icewind1991 are Exceptions handled specifically or in a generic way?

@icewind1991
Copy link
Member

They are handled specifically to have them fancy formatted.

For messages like this, having a guaranteed message field being set that can be shown should be enough, with the rest of the data just being json formatted

@blizzz
Copy link
Member Author

blizzz commented Jan 17, 2020

If this has a chance of being logged to the main log the the logreader will need to be able to handle it

  • in general, it is if some other apps would to this
  • there is, if you set the logfile location to be the nextcloud log file
    • the logreader is crashing in that case

@icewind1991
Copy link
Member

I would prefer to have a string $message parameter though so we always have something human readable in a predictable location

@blizzz blizzz added 2. developing Work in progress and removed 3. to review Waiting for reviews labels Jan 17, 2020
Signed-off-by: Arthur Schiwon <blizzz@arthur-schiwon.de>
also ensure it plays well with current log reader

Signed-off-by: Arthur Schiwon <blizzz@arthur-schiwon.de>
@blizzz blizzz force-pushed the enh/noid/flow-logging branch from 3622d3e to e008444 Compare January 28, 2020 12:00
@blizzz
Copy link
Member Author

blizzz commented Jan 28, 2020

A message parameter is not enough for the logreader, since it just tries to print the delivered payload if it does not match any Exception pattern.

What works better is to split the payload into a message and data part. Then the log reader works as it is now (extra fields are not being show but can be copied rawly).

I don't like the transformation kung foo n LogDetails however, but that's necessary to another field to the log output. Back to review.

@blizzz blizzz added 3. to review Waiting for reviews and removed 2. developing Work in progress labels Jan 28, 2020
@blizzz
Copy link
Member Author

blizzz commented Feb 7, 2020

are we fine with this now? @icewind1991 @rullzer @ChristophWurst

* Interface IDataLogger
*
* @package OCP\Log
* @since 18.0.1
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

19 😉

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Will be back ported

@rullzer rullzer merged commit 1b07dcf into master Feb 10, 2020
@rullzer rullzer deleted the enh/noid/flow-logging branch February 10, 2020 14:09
@backportbot-nextcloud
Copy link

backport to stable18 in #19396

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Projects

None yet

Development

Successfully merging this pull request may close these issues.

6 participants