Office365 plugin stops everynight; requires restart in morning

Before you post: Your responses to these questions will help the community help you. Please complete this template if you’re asking a support question.
Don’t forget to select tags to help index your topic!

1. Describe your incident:
I’ve noticed that our O365 plugin stops ingesting logs (or at least it no longer presents the logs to the stream/dashboard/etc w/in Graylog) every night and requires a restart to get it back going.

2. Describe your environment:

  • OS Information:
    Ubuntu 20.04 in LXC container; Debian 11 Host

  • Package Version:
    Graylog 4.3.1+78ee2f1 + all plugins including Enterprise Trial

  • Service logs, configurations, and environment variables:

This is what is going on at the time the plugin stops working:

2022-06-08T20:00:00.831-04:00 INFO  [AbstractRotationStrategy] Deflector index <Fortigate CEF Logs> (index set <fortigate_cef_1>) should be rotated, Pointing deflector to new index now!
2022-06-08T20:00:00.833-04:00 INFO  [MongoIndexSet] Cycling from <fortigate_cef_1> to <fortigate_cef_2>.
2022-06-08T20:00:00.833-04:00 INFO  [MongoIndexSet] Creating target index <fortigate_cef_2>.
2022-06-08T20:00:00.891-04:00 INFO  [Indices] Successfully ensured index template fortigate_cef-template
2022-06-08T20:00:01.032-04:00 INFO  [MongoIndexSet] Waiting for allocation of index <fortigate_cef_2>.
2022-06-08T20:00:01.039-04:00 INFO  [MongoIndexSet] Index <fortigate_cef_2> has been successfully allocated.
2022-06-08T20:00:01.039-04:00 INFO  [MongoIndexSet] Pointing index alias <fortigate_cef_deflector> to new index <fortigate_cef_2>.
2022-06-08T20:00:01.068-04:00 INFO  [SystemJobManager] Submitted SystemJob <1b900fb0-e787-11ec-89f5-00163ec9a2eb> [org.graylog2.indexer.indices.jobs.SetIndexReadOnlyAndCalculateRangeJob]
2022-06-08T20:00:01.069-04:00 INFO  [MongoIndexSet] Successfully pointed index alias <fortigate_cef_deflector> to index <fortigate_cef_2>.
2022-06-08T20:00:01.080-04:00 INFO  [AbstractRotationStrategy] Deflector index <Graylog Message Failures> (index set <gl-failures_1>) should be rotated, Pointing deflector to new index now!
2022-06-08T20:00:01.081-04:00 INFO  [MongoIndexSet] Cycling from <gl-failures_1> to <gl-failures_2>.
2022-06-08T20:00:01.081-04:00 INFO  [MongoIndexSet] Creating target index <gl-failures_2>.
2022-06-08T20:00:01.097-04:00 INFO  [Indices] Successfully ensured index template gl-failures-template
2022-06-08T20:00:01.195-04:00 INFO  [MongoIndexSet] Waiting for allocation of index <gl-failures_2>.
2022-06-08T20:00:01.197-04:00 INFO  [MongoIndexSet] Index <gl-failures_2> has been successfully allocated.
2022-06-08T20:00:01.198-04:00 INFO  [MongoIndexSet] Pointing index alias <gl-failures_deflector> to new index <gl-failures_2>.
2022-06-08T20:00:01.217-04:00 INFO  [SystemJobManager] Submitted SystemJob <1ba6f310-e787-11ec-89f5-00163ec9a2eb> [org.graylog2.indexer.indices.jobs.SetIndexReadOnlyAndCalculateRangeJob]
2022-06-08T20:00:01.217-04:00 INFO  [MongoIndexSet] Successfully pointed index alias <gl-failures_deflector> to index <gl-failures_2>.
2022-06-08T20:00:31.085-04:00 INFO  [SetIndexReadOnlyJob] Flushing old index <fortigate_cef_1>.
2022-06-08T20:00:31.226-04:00 INFO  [SetIndexReadOnlyJob] Flushing old index <gl-failures_1>.
2022-06-08T20:00:31.229-04:00 INFO  [SetIndexReadOnlyJob] Setting old index <gl-failures_1> to read-only.
2022-06-08T20:00:31.306-04:00 INFO  [SystemJobManager] Submitted SystemJob <2d962aa0-e787-11ec-89f5-00163ec9a2eb> [org.graylog2.indexer.indices.jobs.OptimizeIndexJob]
2022-06-08T20:00:31.309-04:00 INFO  [OptimizeIndexJob] Optimizing index <gl-failures_1>.
2022-06-08T20:00:31.311-04:00 INFO  [CreateNewSingleIndexRangeJob] Calculating ranges for index gl-failures_1.
2022-06-08T20:00:31.318-04:00 INFO  [SystemJobManager] SystemJob <2d962aa0-e787-11ec-89f5-00163ec9a2eb> [org.graylog2.indexer.indices.jobs.OptimizeIndexJob] finished in 12ms.
2022-06-08T20:00:31.331-04:00 INFO  [MongoIndexRangeService] Calculated range of [gl-failures_1] in [18ms].
2022-06-08T20:00:31.332-04:00 INFO  [CreateNewSingleIndexRangeJob] Created ranges for index gl-failures_1.
2022-06-08T20:00:31.337-04:00 INFO  [SystemJobManager] SystemJob <1ba6f310-e787-11ec-89f5-00163ec9a2eb> [org.graylog2.indexer.indices.jobs.SetIndexReadOnlyAndCalculateRangeJob] finished in 119ms.
2022-06-08T20:00:31.348-04:00 INFO  [SetIndexReadOnlyJob] Setting old index <fortigate_cef_1> to read-only.
2022-06-08T20:00:31.417-04:00 INFO  [SystemJobManager] Submitted SystemJob <2da71a90-e787-11ec-89f5-00163ec9a2eb> [org.graylog2.indexer.indices.jobs.OptimizeIndexJob]
2022-06-08T20:00:31.421-04:00 INFO  [OptimizeIndexJob] Optimizing index <fortigate_cef_1>.
2022-06-08T20:00:31.425-04:00 INFO  [CreateNewSingleIndexRangeJob] Calculating ranges for index fortigate_cef_1.
2022-06-08T20:00:31.554-04:00 INFO  [MongoIndexRangeService] Calculated range of [fortigate_cef_1] in [127ms].
2022-06-08T20:00:31.556-04:00 INFO  [CreateNewSingleIndexRangeJob] Created ranges for index fortigate_cef_1.
2022-06-08T20:00:31.561-04:00 INFO  [SystemJobManager] SystemJob <1b900fb0-e787-11ec-89f5-00163ec9a2eb> [org.graylog2.indexer.indices.jobs.SetIndexReadOnlyAndCalculateRangeJob] finished in 491ms.
2022-06-08T20:00:36.145-04:00 INFO  [SystemJobManager] SystemJob <2da71a90-e787-11ec-89f5-00163ec9a2eb> [org.graylog2.indexer.indices.jobs.OptimizeIndexJob] finished in 4727ms

And then nothing until I came in to work and restarted Graylog around 08:15. All other inputs were working, though.

3. What steps have you already taken to try and solve the problem?

Restart the input plugin.

4. How can the community help?

Help me troubleshoot this issue and hopefully prevent it from constantly needing a restart?

Helpful Posting Tips: Tips for Posting Questions that Get Answers [Hold down CTRL and link on link to open tips documents in a separate tab]

I caught it as it happened again; here is what Graylog says via GUI:
The input has encountered errors while fetching data from Microsoft’s O365 servers :: Interrupted acquiring a permit to retrieve an item from the pool

Hello,

Are you referring to this plugin?

Unfortunately, no. I am referring to the plugin that is only available with an Enterprise license: Microsoft Office 365 Input - Operations

Oh, I see.
My apologies I haven’t use Graylog Enterprise Integrations yet.

No worries! Thank you for replying :slight_smile:

This may be helpful (graylog-server log):

2022-06-09T15:56:34.897-04:00 ERROR [Office365Input] The input has encountered errors while fetching data from Microsoft's O365 servers :: Interrupted acquiring a permit to retrieve an item from the pool
com.mongodb.MongoInterruptedException: Interrupted acquiring a permit to retrieve an item from the pool
        at com.mongodb.internal.connection.ConcurrentPool.acquirePermit(ConcurrentPool.java:203) ~[graylog.jar:?]
        at com.mongodb.internal.connection.ConcurrentPool.get(ConcurrentPool.java:140) ~[graylog.jar:?]
        at com.mongodb.internal.connection.DefaultConnectionPool.getPooledConnection(DefaultConnectionPool.java:271) ~[graylog.jar:?]
        at com.mongodb.internal.connection.DefaultConnectionPool.get(DefaultConnectionPool.java:112) ~[graylog.jar:?]
        at com.mongodb.internal.connection.DefaultConnectionPool.get(DefaultConnectionPool.java:101) ~[graylog.jar:?]
        at com.mongodb.internal.connection.DefaultServer.getConnection(DefaultServer.java:92) ~[graylog.jar:?]
        at com.mongodb.binding.ClusterBinding$ClusterBindingConnectionSource.getConnection(ClusterBinding.java:126) ~[graylog.jar:?]
        at com.mongodb.operation.OperationHelper.withReleasableConnection(OperationHelper.java:501) ~[graylog.jar:?]
        at com.mongodb.operation.MixedBulkWriteOperation.execute(MixedBulkWriteOperation.java:196) ~[graylog.jar:?]
        at com.mongodb.operation.BaseWriteOperation.execute(BaseWriteOperation.java:148) ~[graylog.jar:?]
        at com.mongodb.operation.BaseWriteOperation.execute(BaseWriteOperation.java:52) ~[graylog.jar:?]
        at com.mongodb.client.internal.MongoClientDelegate$DelegateOperationExecutor.execute(MongoClientDelegate.java:213) ~[graylog.jar:?]
        at com.mongodb.client.internal.MongoClientDelegate$DelegateOperationExecutor.execute(MongoClientDelegate.java:182) ~[graylog.jar:?]
        at com.mongodb.DBCollection.executeWriteOperation(DBCollection.java:356) ~[graylog.jar:?]
        at com.mongodb.DBCollection.replaceOrInsert(DBCollection.java:436) ~[graylog.jar:?]
        at com.mongodb.DBCollection.save(DBCollection.java:425) ~[graylog.jar:?]
        at org.mongojack.JacksonDBCollection.save(JacksonDBCollection.java:1495) ~[graylog.jar:?]
        at org.mongojack.JacksonDBCollection.save(JacksonDBCollection.java:1476) ~[graylog.jar:?]
        at org.graylog2.inputs.persistence.MongoInputStatusService.save(MongoInputStatusService.java:77) ~[graylog.jar:?]
        at org.graylog.enterprise.integrations.office365.O365PollerTask.storeInputCheckpoint(O365PollerTask.java:148) ~[graylog-plugin-enterprise-integrations-4.3.1.jar:?]
        at org.graylog.enterprise.integrations.office365.O365PollerTask.doRun(O365PollerTask.java:126) ~[graylog-plugin-enterprise-integrations-4.3.1.jar:?]
        at org.graylog.enterprise.integrations.office365.O365PollerTask.run(O365PollerTask.java:51) [graylog-plugin-enterprise-integrations-4.3.1.jar:?]
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515) [?:?]
        at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:305) [?:?]
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:305) [?:?]
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) [?:?]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) [?:?]
        at java.lang.Thread.run(Thread.java:829) [?:?]
Caused by: java.lang.InterruptedException
        at java.util.concurrent.locks.AbstractQueuedSynchronizer.tryAcquireSharedNanos(AbstractQueuedSynchronizer.java:1367) ~[?:?]
        at java.util.concurrent.Semaphore.tryAcquire(Semaphore.java:415) ~[?:?]
        at com.mongodb.internal.connection.ConcurrentPool.acquirePermit(ConcurrentPool.java:197) ~[graylog.jar:?]
        ... 27 more

Mongodb pastebin: Pastebin

I did a quick search on this error.

Interrupted acquiring a permit to retrieve an item from the pool

And it lead me here

https://jira.mongodb.org/browse/JAVA-2091

And here, this post also had a link inside it.

https://groups.google.com/g/mongodb-user/c/gk6Gd9eCmQg

Wish I had this setup in the lab, I would be able to help further.

I decided to give this a try and as far as ingesting it works like a charm but I’ll be darned if I know how to use extractors to get the info all nice and useful

EDIT: I did a bit more digging and I have it up and running and parsed. Thank you so much for the unintentional suggestion; this plug-in is great!

1 Like

Hello @accidentaladmin

No problem this is something I have not tested yet. This does have me think about the plugin and Its on my to-do list.

Can I ask exactly how you resolved this issue? and mark it as resolved for future search’s?

Unfortunately its not so much that the issue is resolved. It is more that I decided to table use of the built-in Office365 plugin (that comes with Enterprise) and went with the plugin you initially referenced (ddbnl’s Office365 Audit Log Collector).

If you are asking how I came to resolving the fact that I could not make sense of the input, I found /u/ddbnl’s article on how to - among other things - manage extractors for the aforementioned plugin: Collecting Office365 & AzureAD audit logs using Office Audit Collector - the NEW Marketplace - Graylog Community

Irrespective, thank you!

1 Like

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