[Filebeat] Okta Module Crashing Frequently

[SpencerLN]

After enabling the Okta module in Filebeat 7.7.0 we have been observing frequent crashes with the error message panic: non-positive interval for NewTicker

Debug logs:

2020-05-14T15:52:45.184Z	DEBUG	[httpjson]	httpjson/input.go:242	Rate Limit: Wait until 2020-05-14 15:52:47 +0000 UTC for the rate limit to reset.	{"url": "https://instance.okta.com/api/v1/logs"}
2020-05-14T15:52:45.600Z	DEBUG	[elasticsearch]	elasticsearch/client.go:217	PublishEvents: 50 events have been published to elasticsearch in 66.640319ms.
2020-05-14T15:52:45.600Z	DEBUG	[publisher]	memqueue/ackloop.go:160	ackloop: receive ack [236: 0, 50]
2020-05-14T15:52:45.601Z	DEBUG	[publisher]	memqueue/eventloop.go:535	broker ACK events: count=50, start-seq=11701, end-seq=11750
2020-05-14T15:52:45.601Z	DEBUG	[publisher]	memqueue/ackloop.go:128	ackloop: return ack to broker loop:50
2020-05-14T15:52:45.601Z	DEBUG	[acker]	beater/acker.go:69	stateless ack	{"count": 50}
2020-05-14T15:52:45.601Z	DEBUG	[publisher]	memqueue/ackloop.go:131	ackloop:  done send ack
2020-05-14T15:52:45.697Z	DEBUG	[elasticsearch]	elasticsearch/client.go:217	PublishEvents: 50 events have been published to elasticsearch in 96.090322ms.
2020-05-14T15:52:45.699Z	DEBUG	[publisher]	memqueue/ackloop.go:160	ackloop: receive ack [237: 0, 50]
2020-05-14T15:52:45.699Z	DEBUG	[publisher]	memqueue/eventloop.go:535	broker ACK events: count=50, start-seq=11751, end-seq=11800
2020-05-14T15:52:45.699Z	DEBUG	[publisher]	memqueue/ackloop.go:128	ackloop: return ack to broker loop:50
2020-05-14T15:52:45.699Z	DEBUG	[publisher]	memqueue/ackloop.go:131	ackloop:  done send ack
2020-05-14T15:52:45.699Z	DEBUG	[acker]	beater/acker.go:69	stateless ack	{"count": 50}
2020-05-14T15:52:45.799Z	DEBUG	[elasticsearch]	elasticsearch/client.go:217	PublishEvents: 50 events have been published to elasticsearch in 101.995502ms.
2020-05-14T15:52:45.799Z	DEBUG	[publisher]	memqueue/ackloop.go:160	ackloop: receive ack [238: 0, 50]
2020-05-14T15:52:45.799Z	DEBUG	[publisher]	memqueue/eventloop.go:535	broker ACK events: count=50, start-seq=11801, end-seq=11850
2020-05-14T15:52:45.799Z	DEBUG	[publisher]	memqueue/ackloop.go:128	ackloop: return ack to broker loop:50
2020-05-14T15:52:45.800Z	DEBUG	[publisher]	memqueue/ackloop.go:131	ackloop:  done send ack
2020-05-14T15:52:45.800Z	DEBUG	[acker]	beater/acker.go:69	stateless ack	{"count": 50}
2020-05-14T15:52:45.913Z	DEBUG	[elasticsearch]	elasticsearch/client.go:217	PublishEvents: 50 events have been published to elasticsearch in 113.897908ms.
2020-05-14T15:52:45.913Z	DEBUG	[publisher]	memqueue/ackloop.go:160	ackloop: receive ack [239: 0, 50]
2020-05-14T15:52:45.913Z	DEBUG	[publisher]	memqueue/eventloop.go:535	broker ACK events: count=50, start-seq=11851, end-seq=11900
2020-05-14T15:52:45.913Z	DEBUG	[publisher]	memqueue/ackloop.go:128	ackloop: return ack to broker loop:50
2020-05-14T15:52:45.913Z	DEBUG	[publisher]	memqueue/ackloop.go:131	ackloop:  done send ack
2020-05-14T15:52:45.914Z	DEBUG	[acker]	beater/acker.go:69	stateless ack	{"count": 50}
2020-05-14T15:52:47.000Z	DEBUG	[httpjson]	httpjson/input.go:250	Rate Limit: time is up.	{"url": "https://instance.okta.com/api/v1/logs"}
2020-05-14T15:52:47.000Z	INFO	[httpjson]	httpjson/input.go:366	Continuing with pagination to URL: https://instance.okta.com/api/v1/logs?after=1588875667507_1	{"url": "https://instance.okta.com/api/v1/logs"}
2020-05-14T15:52:47.194Z	DEBUG	[httpjson]	httpjson/input.go:302	HTTP request failed	{"url": "https://instance.okta.com/api/v1/logs", "http.response.status_code": 429, "http.response.body": "{\"errorCode\":\"E0000047\",\"errorSummary\":\"API call exceeded rate limit due to too many requests.\",\"errorLink\":\"E0000047\",\"errorId\":\"oae26ps49lmR7m6OmE6oSGLyA\",\"errorCauses\":[]}"}
2020-05-14T15:52:47.194Z	DEBUG	[httpjson]	httpjson/input.go:242	Rate Limit: Wait until 2020-05-14 15:52:47 +0000 UTC for the rate limit to reset.	{"url": "https://instance.okta.com/api/v1/logs"}
2020-05-14T15:52:47.194Z	INFO	[httpjson]	runtime/panic.go:679	httpjson input worker has stopped.	{"url": "https://instance.okta.com/api/v1/logs"}
panic: non-positive interval for NewTicker
goroutine 272 [running]:
time.NewTicker(0xfffffffff469c21f, 0xed64f604f)
	/usr/local/go/src/time/tick.go:23 +0x147
github.com/elastic/beats/v7/x-pack/filebeat/input/httpjson.(*HttpjsonInput).applyRateLimit(0xc0006460f0, 0x3e13a20, 0xc000654140, 0xc001940060, 0xc0004c5560, 0x0, 0x0)
	/go/src/github.com/elastic/beats/x-pack/filebeat/input/httpjson/input.go:243 +0x1a2
github.com/elastic/beats/v7/x-pack/filebeat/input/httpjson.(*HttpjsonInput).processHTTPRequest(0xc0006460f0, 0x3e13a20, 0xc000654140, 0xc0006425a0, 0xc0005b9e08, 0xdf8475800, 0x3da8ae0)
	/go/src/github.com/elastic/beats/x-pack/filebeat/input/httpjson/input.go:304 +0x337
github.com/elastic/beats/v7/x-pack/filebeat/input/httpjson.(*HttpjsonInput).run(0xc0006460f0, 0x0, 0x0)
	/go/src/github.com/elastic/beats/x-pack/filebeat/input/httpjson/input.go:425 +0x38f
github.com/elastic/beats/v7/x-pack/filebeat/input/httpjson.(*HttpjsonInput).Run.func1.1(0xc0006460f0)
	/go/src/github.com/elastic/beats/x-pack/filebeat/input/httpjson/input.go:122 +0x1d6
created by github.com/elastic/beats/v7/x-pack/filebeat/input/httpjson.(*HttpjsonInput).Run.func1
	/go/src/github.com/elastic/beats/x-pack/filebeat/input/httpjson/input.go:117 +0x63

Config:

   filebeat.yml: |-
    filebeat.modules:
    - module: okta
      system:
        enabled: true
        # API key to access Okta
        var.api_key: "${OKTA_API_KEY}"

        # URL of the Okta REST API
        var.url: ${OKTA_API_URL}

        var.authentication_scheme: "SSWS"
    setup.template.enabled: false

    output.elasticsearch:
        hosts: 'https://${ELASTICSEARCH_ADDRESS}'
        username: ${ELASTICSEARCH_USERNAME}
        password: ${ELASTICSEARCH_PASSWORD}
        ssl:
          enabled: true
          supported_protocols: TLSv1.2
    logging.level: debug

For confirmed bugs, please report:

• Version: 7.7.0
• Operating System: GKE CoreOS

[elasticmachine]

Pinging @elastic/siem (Team:SIEM)

[SpencerLN]

It appears that this issue is still occurring after upgrade to 7.8.0:

2020-06-25T20:01:47.000Z	INFO	[httpjson]	httpjson/input.go:366	Continuing with pagination to URL: https://instance.okta.com/api/v1/logs?after=1592620709654_1	{"url": "https://instance.okta.com/api/v1/logs"}
2020-06-25T20:01:47.039Z	DEBUG	[input]	input/input.go:141	Run input
2020-06-25T20:01:47.175Z	DEBUG	[httpjson]	httpjson/input.go:302	HTTP request failed	{"url": "https://instance.okta.com/api/v1/logs", "http.response.status_code": 429, "http.response.body": "{\"errorCode\":\"E0000047\",\"errorSummary\":\"API call exceeded rate limit due to too many requests.\",\"errorLink\":\"E0000047\",\"errorId\":\"oaeWBRMYbglSkiPyH-qA_nmow\",\"errorCauses\":[]}"}
2020-06-25T20:01:47.175Z	DEBUG	[httpjson]	httpjson/input.go:242	Rate Limit: Wait until 2020-06-25 20:01:47 +0000 UTC for the rate limit to reset.	{"url": "https://instance.okta.com/api/v1/logs"}
2020-06-25T20:01:47.175Z	INFO	[httpjson]	runtime/panic.go:679	httpjson input worker has stopped.	{"url": "https://instance.okta.com/api/v1/logs"}
panic: non-positive interval for NewTicker

goroutine 260 [running]:
time.NewTicker(0xfffffffff586a07f, 0xed686f9ab)
	/usr/local/go/src/time/tick.go:23 +0x147
github.com/elastic/beats/v7/x-pack/filebeat/input/httpjson.(*HttpjsonInput).applyRateLimit(0xc0006140f0, 0x3f6d120, 0xc0006082c0, 0xc0018af200, 0xc00047ba40, 0x0, 0x0)
	/go/src/github.com/elastic/beats/x-pack/filebeat/input/httpjson/input.go:243 +0x1a2
github.com/elastic/beats/v7/x-pack/filebeat/input/httpjson.(*HttpjsonInput).processHTTPRequest(0xc0006140f0, 0x3f6d120, 0xc0006082c0, 0xc0005eb170, 0xc001ed9e08, 0xdf8475800, 0x3eff400)
	/go/src/github.com/elastic/beats/x-pack/filebeat/input/httpjson/input.go:304 +0x337
github.com/elastic/beats/v7/x-pack/filebeat/input/httpjson.(*HttpjsonInput).run(0xc0006140f0, 0x0, 0x0)
	/go/src/github.com/elastic/beats/x-pack/filebeat/input/httpjson/input.go:425 +0x38f
github.com/elastic/beats/v7/x-pack/filebeat/input/httpjson.(*HttpjsonInput).Run.func1.1(0xc0006140f0)
	/go/src/github.com/elastic/beats/x-pack/filebeat/input/httpjson/input.go:122 +0x1d6
created by github.com/elastic/beats/v7/x-pack/filebeat/input/httpjson.(*HttpjsonInput).Run.func1
	/go/src/github.com/elastic/beats/x-pack/filebeat/input/httpjson/input.go:117 +0x63

[vavra5]

I'm experiencing the same issue. My configuration is same as provided above. I'm using docker container filebeat:7.8.0.

2020-06-26T15:04:33.000Z	INFO	[httpjson]	httpjson/input.go:366	Continuing with pagination to URL: https://my.okta.com/api/v1/logs?after=1592593036919_1	{"url": "https://my.okta.com/api/v1/logs"}
2020-06-26T15:04:33.094Z	INFO	[httpjson]	runtime/panic.go:679	httpjson input worker has stopped.	{"url": "https://my.okta.com/api/v1/logs"}
panic: non-positive interval for NewTicker
goroutine 310 [running]:
time.NewTicker(0xfffffffffa5cf692, 0xed6880581)
	/usr/local/go/src/time/tick.go:23 +0x147
github.com/elastic/beats/v7/x-pack/filebeat/input/httpjson.(*HttpjsonInput).applyRateLimit(0xc00049c3c0, 0x3f6d120, 0xc000866c40, 0xc001239e30, 0xc000782d20, 0x0, 0x0)
	/go/src/github.com/elastic/beats/x-pack/filebeat/input/httpjson/input.go:243 +0x1a2
github.com/elastic/beats/v7/x-pack/filebeat/input/httpjson.(*HttpjsonInput).processHTTPRequest(0xc00049c3c0, 0x3f6d120, 0xc000866c40, 0xc00086bb00, 0xc001b61e08, 0xdf8475800, 0x3eff400)
	/go/src/github.com/elastic/beats/x-pack/filebeat/input/httpjson/input.go:304 +0x337
github.com/elastic/beats/v7/x-pack/filebeat/input/httpjson.(*HttpjsonInput).run(0xc00049c3c0, 0x0, 0x0)
	/go/src/github.com/elastic/beats/x-pack/filebeat/input/httpjson/input.go:425 +0x38f
github.com/elastic/beats/v7/x-pack/filebeat/input/httpjson.(*HttpjsonInput).Run.func1.1(0xc00049c3c0)
	/go/src/github.com/elastic/beats/x-pack/filebeat/input/httpjson/input.go:122 +0x1d6
created by github.com/elastic/beats/v7/x-pack/filebeat/input/httpjson.(*HttpjsonInput).Run.func1
	/go/src/github.com/elastic/beats/x-pack/filebeat/input/httpjson/input.go:117 +0x63

[SpencerLN]

@alakahakai it looks like this is being corrected by handling a specific rate-limit condition. Is there any chance of handling this by adding some sort of generic retry mechanism that makes the whole input more resilient to transient errors? Right now the input is prone to crashing when any sort of unexpected behavior occurs.

[SpencerLN]

@alakahakai after upgrading to 7.8.1 we saw a significant improvement and the module is no longer crashing due to rate limiting constantly, but there appear to still be conditions that cause a crash. As mentioned above, it would be ideal to implement some sort of generic retry logic for retryable error conditions.

Our most recent instance, after running for ~12 hours:

2020-07-28T08:44:24.477Z	ERROR	[httpjson]	httpjson/input.go:123	http request was unsuccessful with a status code 504	{"url": "https://instance.okta.com/api/v1/logs"}
2020-07-28T08:44:24.477Z	INFO	[httpjson]	httpjson/input.go:124	httpjson input worker has stopped.	{"url": "https://instance.okta.com/api/v1/logs"}

[andrewkroh]

Two fixes for the Okta module will be released in v7.9.0.

• Address Okta input issue #18530 #18534 addresses this specific issue. This fix missed the cutoff for 7.8.1 and there was never a 7.8.2 release so it will be in 7.9.0.
• Add automatic retries and exponential backoff to Filebeat httpjson input #18956 improves overall reliability by retrying on connectivity and HTTP errors.

Then looking forward to v7.10.0 we plan to make the module be able to persist the last read event timestamp and be able to resume reading from the point on restart. Part of that work is in happening in #20226.