Client.Timeout for Exchange/General/Sharepoint

[kevinserafin]

Hello, I'm attempting to use o365beat and I am able to get events from Audit.AzureActiveDirectory but any of the other three all fail with a client.timeout. Am I wrong to assume that the audit logging is turned on since I am able to retrieve AzureAD logs?

2020-02-25T15:14:18.368-0600    DEBUG   [api]   beater/o365beat.go:279  getting next page of results from NextPageUri: https://manage.office.com/api/v1.0/{{tenantID}}/activity/feed/subscriptions/content?contenttype=Audit.General&endtime=2020-02-20T10:46:42.0000000Z&starttime=2020-02-19T10:46:42.0000000Z&nextpage=20200220001806300068349$20200219104642000000000$na0022
2020-02-25T15:14:18.369-0600    DEBUG   [api]   beater/o365beat.go:112  issuing api request: https://manage.office.com/api/v1.0/{{tenantID}}/activity/feed/subscriptions/content?PublisherIdentifier={{tenantID}}&contenttype=Audit.General&endtime=2020-02-20T10%3A46%3A42.0000000Z&nextpage=20200220001806300068349%2420200219104642000000000%24na0022&starttime=2020-02-19T10%3A46%3A42.0000000Z
2020-02-25T15:14:19.954-0600    DEBUG   [api]   beater/o365beat.go:279  getting next page of results from NextPageUri: https://manage.office.com/api/v1.0/{{tenantID}}/activity/feed/subscriptions/content?contenttype=Audit.General&endtime=2020-02-20T10:46:42.0000000Z&starttime=2020-02-19T10:46:42.0000000Z&nextpage=20200220003621012087066$20200219104642000000000$na0022
2020-02-25T15:14:19.954-0600    DEBUG   [api]   beater/o365beat.go:112  issuing api request: https://manage.office.com/api/v1.0/{{tenantID}}/activity/feed/subscriptions/content?PublisherIdentifier={{tenantID}}&contenttype=Audit.General&endtime=2020-02-20T10%3A46%3A42.0000000Z&nextpage=20200220003621012087066%2420200219104642000000000%24na0022&starttime=2020-02-19T10%3A46%3A42.0000000Z
2020-02-25T15:14:21.769-0600    DEBUG   [api]   beater/o365beat.go:279  getting next page of results from NextPageUri: https://manage.office.com/api/v1.0/{{tenantID}}/activity/feed/subscriptions/content?contenttype=Audit.General&endtime=2020-02-20T10:46:42.0000000Z&starttime=2020-02-19T10:46:42.0000000Z&nextpage=20200220010537625168694$20200219104642000000000$na0022
2020-02-25T15:14:21.769-0600    DEBUG   [api]   beater/o365beat.go:112  issuing api request: https://manage.office.com/api/v1.0/{{tenantID}}/activity/feed/subscriptions/content?PublisherIdentifier={{tenantID}}&contenttype=Audit.General&endtime=2020-02-20T10%3A46%3A42.0000000Z&nextpage=20200220010537625168694%2420200219104642000000000%24na0022&starttime=2020-02-19T10%3A46%3A42.0000000Z
2020-02-25T15:14:22.763-0600    INFO    [monitoring]    log/log.go:145  Non-zero metrics in the last 30s    {"monitoring": {"metrics": {"beat":{"cpu":{"system":{"ticks":135,"time":{"ms":13}},"total":{"ticks":453,"time":{"ms":43},"value":453},"user":{"ticks":318,"time":{"ms":30}}},"info":{"ephemeral_id":"8a86dd31-aa3c-40d8-aeab-d3f7fbfe87b2","uptime":{"ms":240065}},"memstats":{"gc_next":7404752,"memory_alloc":5387160,"memory_total":43785384,"rss":20480},"runtime":{"goroutines":13}},"libbeat":{"config":{"module":{"running":0}},"pipeline":{"clients":1,"events":{"active":0}}},"system":{"load":{"1":3.6611,"15":3.6367,"5":3.6147,"norm":{"1":0.4576,"15":0.4546,"5":0.4518}}}}}}
2020-02-25T15:14:51.775-0600    INFO    [monitoring]    log/log.go:153  Total non-zero metrics  {"monitoring": {"metrics": {"beat":{"cpu":{"system":{"ticks":137,"time":{"ms":137}},"total":{"ticks":459,"time":{"ms":459},"value":459},"user":{"ticks":322,"time":{"ms":322}}},"info":{"ephemeral_id":"8a86dd31-aa3c-40d8-aeab-d3f7fbfe87b2","uptime":{"ms":269073}},"memstats":{"gc_next":7404752,"memory_alloc":6479216,"memory_total":44877440,"rss":32579584},"runtime":{"goroutines":10}},"libbeat":{"config":{"module":{"running":0}},"output":{"type":"elasticsearch"},"pipeline":{"clients":1,"events":{"active":0}}},"system":{"cpu":{"cores":8},"load":{"1":3.6987,"15":3.6426,"5":3.6328,"norm":{"1":0.4623,"15":0.4553,"5":0.4541}}}}}}
2020-02-25T15:14:51.775-0600    INFO    [monitoring]    log/log.go:154  Uptime: 4m29.077678404s
2020-02-25T15:14:51.776-0600    INFO    [monitoring]    log/log.go:131  Stopping metrics logging.
2020-02-25T15:14:51.776-0600    INFO    instance/beat.go:435    o365beat stopped.
2020-02-25T15:14:51.776-0600    ERROR   instance/beat.go:916    Exiting: error listing all available content between 2020-02-19 10:46:42 +0000 UTC and 2020-02-25 15:10:25.407664 -0600 CST m=+2.740111375: Get https://manage.office.com/api/v1.0/{{tenantID}}/activity/feed/subscriptions/content?PublisherIdentifier={{tenantID}}&contenttype=Audit.General&endtime=2020-02-20T10%3A46%3A42.0000000Z&nextpage=20200220010537625168694%2420200219104642000000000%24na0022&starttime=2020-02-19T10%3A46%3A42.0000000Z: net/http: request canceled (Client.Timeout exceeded while awaiting headers)
Exiting: error listing all available content between 2020-02-19 10:46:42 +0000 UTC and 2020-02-25 15:10:25.407664 -0600 CST m=+2.740111375: Get https://manage.office.com/api/v1.0/{{tenantID}}/activity/feed/subscriptions/content?PublisherIdentifier={{tenantID}}&contenttype=Audit.General&endtime=2020-02-20T10%3A46%3A42.0000000Z&nextpage=20200220010537625168694%2420200219104642000000000%24na0022&starttime=2020-02-19T10%3A46%3A42.0000000Z: net/http: request canceled (Client.Timeout exceeded while awaiting headers)

2020-02-25T16:09:02.210-0600    DEBUG   [api]   beater/o365beat.go:279  getting next page of results from NextPageUri: https://manage.office.com/api/v1.0/{{tenantID}}/activity/feed/subscriptions/content?contenttype=Audit.Exchange&endtime=2020-02-20T10:46:42.0000000Z&starttime=2020-02-19T10:46:42.0000000Z&nextpage=20200220003934923146674$20200219104642000000000$na0022
2020-02-25T16:09:02.210-0600    DEBUG   [api]   beater/o365beat.go:112  issuing api request: https://manage.office.com/api/v1.0/{{tenantID}}/activity/feed/subscriptions/content?PublisherIdentifier={{tenantID}}&contenttype=Audit.Exchange&endtime=2020-02-20T10%3A46%3A42.0000000Z&nextpage=20200220003934923146674%2420200219104642000000000%24na0022&starttime=2020-02-19T10%3A46%3A42.0000000Z
2020-02-25T16:09:18.069-0600    INFO    [monitoring]    log/log.go:145  Non-zero metrics in the last 30s    {"monitoring": {"metrics": {"beat":{"cpu":{"system":{"ticks":232,"time":{"ms":10}},"total":{"ticks":784,"time":{"ms":35},"value":784},"user":{"ticks":552,"time":{"ms":25}}},"info":{"ephemeral_id":"aa261288-f9d2-473e-a654-3afc0da61359","uptime":{"ms":420083}},"memstats":{"gc_next":8027264,"memory_alloc":5188720,"memory_total":77670584,"rss":540672},"runtime":{"goroutines":13}},"libbeat":{"config":{"module":{"running":0}},"pipeline":{"clients":1,"events":{"active":0}}},"system":{"load":{"1":3.25,"15":3.2871,"5":3.2778,"norm":{"1":0.4063,"15":0.4109,"5":0.4097}}}}}}
2020-02-25T16:09:32.218-0600    INFO    [monitoring]    log/log.go:153  Total non-zero metrics  {"monitoring": {"metrics": {"beat":{"cpu":{"system":{"ticks":234,"time":{"ms":234}},"total":{"ticks":790,"time":{"ms":791},"value":790},"user":{"ticks":556,"time":{"ms":557}}},"info":{"ephemeral_id":"aa261288-f9d2-473e-a654-3afc0da61359","uptime":{"ms":434231}},"memstats":{"gc_next":8027264,"memory_alloc":4852192,"memory_total":78240840,"rss":33533952},"runtime":{"goroutines":10}},"libbeat":{"config":{"module":{"running":0}},"output":{"type":"elasticsearch"},"pipeline":{"clients":1,"events":{"active":0}}},"system":{"cpu":{"cores":8},"load":{"1":3.9014,"15":3.334,"5":3.4126,"norm":{"1":0.4877,"15":0.4167,"5":0.4266}}}}}}
2020-02-25T16:09:32.218-0600    INFO    [monitoring]    log/log.go:154  Uptime: 7m14.232693213s
2020-02-25T16:09:32.218-0600    INFO    [monitoring]    log/log.go:131  Stopping metrics logging.
2020-02-25T16:09:32.218-0600    INFO    instance/beat.go:435    o365beat stopped.
2020-02-25T16:09:32.219-0600    ERROR   instance/beat.go:916    Exiting: error listing all available content between 2020-02-19 10:46:42 +0000 UTC and 2020-02-25 16:02:18.876632 -0600 CST m=+0.940801257: Get https://manage.office.com/api/v1.0/{{tenantID}}/activity/feed/subscriptions/content?PublisherIdentifier={{tenantID}}&contenttype=Audit.Exchange&endtime=2020-02-20T10%3A46%3A42.0000000Z&nextpage=20200220003934923146674%2420200219104642000000000%24na0022&starttime=2020-02-19T10%3A46%3A42.0000000Z: net/http: request canceled (Client.Timeout exceeded while awaiting headers)
Exiting: error listing all available content between 2020-02-19 10:46:42 +0000 UTC and 2020-02-25 16:02:18.876632 -0600 CST m=+0.940801257: Get https://manage.office.com/api/v1.0/{{tenantID}}/activity/feed/subscriptions/content?PublisherIdentifier={{tenantID}}&contenttype=Audit.Exchange&endtime=2020-02-20T10%3A46%3A42.0000000Z&nextpage=20200220003934923146674%2420200219104642000000000%24na0022&starttime=2020-02-19T10%3A46%3A42.0000000Z: net/http: request canceled (Client.Timeout exceeded while awaiting headers)

[kevinserafin]

Started digging into it a little bit, i've verified that auditing is enabled.

[{"contentType":"Audit.AzureActiveDirectory","status":"enabled","webhook":null},{"contentType":"Audit.Exchange","status":"enabled","webhook":null},{"contentType":"Audit.General","status":"enabled","webhook":null},{"contentType":"Audit.SharePoint","status":"enabled","webhook":null}]

[ion-storm]

same issue happened to me with sharepoint, testing the others..

[victor-ide]

Same issue, tried pooling data from Audit.AzureActiveDirectory, Audit.Exchange, Audit.SharePoint, Audit.General, no luck.

[kevinserafin]

I was poking around the code last night (config.go) and found there are a few properties that can be set for api_timeout and content_max_age.

o365beat:
  content_max_age: 120

This started working quickly once it wasn't trying to go back a week, we have a really busy tenant so i'm sure the volume was a bit much for it to pull. It would be good to document some of these settings in the sample config with a description of how to set them or what the interval is.

[chris-counteractive]

Thank you @kevinserafin for pointing this out, there are indeed a few parameters you can tweak that we didn't emphasize in the documentation. We've not run into this before, I appreciate the chance to update the docs with some some specifics. The idea that pulling a long span on a busy tenant could push you closer to a timeout makes sense, I'll do my best to capture that in an FAQ item and in the config discussion in the README. I'll let you know when it's updated, if you think it covers your issue we can close this. Thanks again!

[kevinserafin]

Sounds good, this is a great tool - appreciate the work!