Portfolio MS Teams Notification are not being sent

[Kretikus]

Current Behavior

Hi,

our teams notification are not beind sent from out Dependencytrack.

We use following Configuration:

System-Notifications with the same Web-Hook URL are being sent and received.

Do we overlook things?

Steps to Reproduce

1. Configure the Teams Notification as in the screen shot above

2. If projects get new vulnerabilities no notification is sent

Expected Behavior

The notification should have been sent

Dependency-Track Version

4.7.1

Dependency-Track Distribution

Container Image

Database Server

Microsoft SQL Server

Database Server Version

SQL 2017

Browser

Google Chrome

Checklist

• [X] I have read and understand the contributing guidelines
• [X] I have checked the existing issues for whether this defect was already reported

[syalioune]

Hello @Kretikus Do you see anything particular on the logs ? Can you share the logs ?

[clemlesne]

I confirm the behavior.

[syalioune]

Hello @clemlesne

Same questions :-) ! Do you see anything particular in the logs ? MS Teams notifications worked in my previous company. Unfortunately I don't have a Teams instance for testing right now.

[pacmms]

Hello, could it be, that all portfolio notifications are not working? I use version 4.8.2 in docker environment. System notfications are working as expected. Nothing in the logs (Level Debug). I tried mail,webhook and console.

[ag-lls]

Same here, half a year later 🤷‍♂️, not working at all on Portfolio level for MS Teams. System level works fine 👍 v.4.9.1 edit: on v4.10.1 also

[nscuro]

Ensuring integrations with 3rd party services like MS Teams continue to work is challenging because there's no straightforward way to test it in an automated fashion. All we can do is verify that whatever we sent matches what the service is expecting based on its API documentation.

As of DT v4.10, you can enable explicit logging of notifications that DT has sent: https://docs.dependencytrack.org/integrations/notifications/#debugging-missing-notifications

This will help to determine whether it's DT not even sending anything, or the service accepting it but silently dropping it.

[ag-lls]

Thanks for the quick response. I know that's a difficult topic. I tried with 4.10.1 and neither do I get a success log in the console, nor does my RequestBin receive anything. So I am guessing DT just doesn't send it. System level works like a charm 👍

[ag-lls]

@nscuro I just tested email notifications, they also don't work. And like with MS Teams, System Level works fine, it's just Portfolio level.

So maybe there is an actual issue in the code regarding Portfolio level notifications?

[lukas-braune]

Based on my observations with DT v4.10.1, MS Teams notifications (with scope PORTFOLIO) seem to have sporadic dropouts. In such instances, no errors are logged either.

[daknhh]

Any update on this? We desperately need notifications for teams and email to work.

[nscuro]

All I can see from my local testing with DT v4.10.1, is that notifications for MS Teams with scope PORTFOLIO are being sent out as expected, in the expected format.

I am unable to reproduce a scenario where notifications would be dropped. I don't have an MS Teams instance that I can use for a "true" end-to-end test.

With LOGGING_LEVEL=DEBUG, I'm seeing these logs being emitted:

2024-03-18 21:22:57,938 DEBUG [NotificationRouter] Matched 1 notification rules (PublishContext{notificationGroup=BOM_CONSUMED, notificationLevel=INFORMATIONAL, notificationScope=PORTFOLIO, notificationTimestamp=2024-03-18T21:22:57.93559721Z, notificationSubjects={project=Project[uuid=36d9daa8-35a5-4bb3-8681-be04340ec7b2, name=foo, version=null]}})
2024-03-18 21:22:57,938 DEBUG [NotificationRouter] Rule is not limited to projects; Rule is applicable (PublishContext{notificationGroup=BOM_CONSUMED, notificationLevel=INFORMATIONAL, notificationScope=PORTFOLIO, notificationTimestamp=2024-03-18T21:22:57.93559721Z, notificationSubjects={project=Project[uuid=36d9daa8-35a5-4bb3-8681-be04340ec7b2, name=foo, version=null]}, ruleName=Foo, ruleScope=PORTFOLIO, ruleLevel=INFORMATIONAL})
2024-03-18 21:22:57,938 DEBUG [NotificationRouter] Applicable rules: Foo (PublishContext{notificationGroup=BOM_CONSUMED, notificationLevel=INFORMATIONAL, notificationScope=PORTFOLIO, notificationTimestamp=2024-03-18T21:22:57.93559721Z, notificationSubjects={project=Project[uuid=36d9daa8-35a5-4bb3-8681-be04340ec7b2, name=foo, version=null]}})
2024-03-18 21:22:59,272 INFO [MsTeamsPublisher] Destination acknowledged reception of notification with status code 200 (PublishContext{notificationGroup=BOM_CONSUMED, notificationLevel=INFORMATIONAL, notificationScope=PORTFOLIO, notificationTimestamp=2024-03-18T21:22:57.93559721Z, notificationSubjects={project=Project[uuid=36d9daa8-35a5-4bb3-8681-be04340ec7b2, name=foo, version=null]}, ruleName=Foo, ruleScope=PORTFOLIO, ruleLevel=INFORMATIONAL})

If the above entries are not appearing in your case, then the condition for the notification in question was never even triggered.

On a related note, I found multiple posts in the Microsoft support forums, indicating that MS Teams sometimes responds to Webhooks with HTTP 200 OK, even though it failed to process. For example: https://answers.microsoft.com/en-us/msteams/forum/all/teams-webhook-error-despite-200-ok/920464d2-dd9c-4fae-847a-99855f6498f2

This does not explain why some of you do not see any notifications at all, but may be related to what @lukas-braune is reporting.

[lukas-braune]

Thanks @nscuro for the quick investigation. Still I don't think that the MS Teams issue discussed in Microsoft's support forum is related to my report because I don't even see the corresponding log message (Destination acknowledged reception of notification with status code 200).

[black-snow]

2024-05-06 07:55:00,727 WARN [MsTeamsPublisher] Destination responded with with status code 405, likely indicating a processing failure (PublishContext{notificationGroup=BOM_CONSUMED, notificationLevel=INFORMATIONAL, notificationScope=PORTFOLIO, notificationTimestamp=2024-05-06T07:55:00.643617338Z, notificationSubjects={project=Project[uuid=5a93ce6d-0395-45e8-9593-859eaa3f765b, name=xxx, version=latest]}, ruleName=test-teams, ruleScope=PORTFOLIO, ruleLevel=INFORMATIONAL})

Reads like it was using the wrong HTTP verb o_Ò

But it's a post and it should be a post.
This is a real blocker for us. I'm a bit puzzled what's happening here.

/edit: manually posting to https://teams.microsoft.com/l/channel/xyz... yields a 405, too. Returns allow: GET, HEAD ò.Ò
/edit2: well, looks like I'm stupid - need to create a webhook instead /edit3: runs fine with webhooks - cannot repro the OP

[JaccoDieleman]

Is there any new on this one? I'm having the same problem. I turned on LOGGING_LEVEL=DEBUG to see what's happening.

For SYSTEM scope notifications work and I see the following in the logging:

...
2024-06-19 14:12:54,484 INFO [UserResource] Managed user created: *** by: ******** / IP Address: ******* / User Agent: Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:127.0) Gecko/20100101 Firefox/127.0
2024-06-19 14:12:54,485 DEBUG [NotificationService] Dispatching notification: class alpine.notification.Notification
2024-06-19 14:12:54,485 DEBUG [NotificationService] Alerting subscriber org.dependencytrack.notification.NotificationRouter
2024-06-19 14:12:54,501 DEBUG [NotificationRouter] Matched 1 notification rules (PublishContext{notificationGroup=USER_CREATED, notificationLevel=INFORMATIONAL, notificationScope=SYSTEM, notificationTimestamp=2024-06-19T14:12:54.485095114Z, notificationSubjects={}})
2024-06-19 14:12:55,708 INFO [MsTeamsPublisher] Destination acknowledged reception of notification with status code 200 (PublishContext{notificationGroup=USER_CREATED, notificationLevel=INFORMATIONAL, notificationScope=SYSTEM, notificationTimestamp=2024-06-19T14:12:54.485095114Z, notificationSubjects={}, ruleName=SystemNotifications, ruleScope=SYSTEM, ruleLevel=INFORMATIONAL})
...

For PORTFOLIO scope notifications do not work. For the notification configuration I checked all the boxes under Group (including PROJECT_CREATED) however nothing happens in Teams nor in my mock server (Postman). This I what I see in the logging:

...
2024-06-19 14:11:10,192 DEBUG [IW] 0 msec to finish stored fields
2024-06-19 14:11:10,192 INFO [ProjectResource] Project foo32 created by ***
2024-06-19 14:11:10,193 DEBUG [IW] 0 msec to write postings and finish vectors
2024-06-19 14:11:10,193 DEBUG [IW] 0 msec to write fieldInfos
2024-06-19 14:11:10,193 DEBUG [DWPT] new segment has 0 deleted docs
2024-06-19 14:11:10,193 DEBUG [DWPT] new segment has 0 soft-deleted docs
2024-06-19 14:11:10,193 DEBUG [DWPT] new segment has no vectors; norms; no docValues; prox; freqs
2024-06-19 14:11:10,193 DEBUG [DWPT] flushedFiles=[_2_Lucene84_0.doc, _2.nvd, _2_Lucene84_0.tim, _2.fdm, _2_Lucene84_0.pos, _2.fdt, _2.nvm, _2.fnm, _2.fdx, _2_Lucene84_0.tip, _2_Lucene84_0.tmd]
2024-06-19 14:11:10,193 DEBUG [DWPT] flushed codec=Lucene87
2024-06-19 14:11:10,193 DEBUG [DWPT] flushed: segment=_2 ramUsed=0.073 MB newFlushedSize=0.002 MB docs/MB=646.471
2024-06-19 14:11:10,193 DEBUG [IW] create compound file
2024-06-19 14:11:10,194 DEBUG [DWPT] flush time 2.785872 msec
2024-06-19 14:11:10,194 DEBUG [IW] publishFlushedSegment seg-private updates=null
2024-06-19 14:11:10,194 DEBUG [IW] publishFlushedSegment _2(8.11.3):c1:[diagnostics={os=Linux, java.vendor=Eclipse Adoptium, java.version=21.0.3, java.vm.version=21.0.3+9-LTS, lucene.version=8.11.3, os.arch=amd64, java.runtime.version=21.0.3+9-LTS, source=flush, os.version=5.15.0-1064-azure, timestamp=1718806270193}]:[attributes={Lucene87StoredFieldsFormat.mode=BEST_SPEED}] :id=9h21l1jsclcghiszkf7l6822a
2024-06-19 14:11:10,194 DEBUG [BD] finished packet delGen=3 now completedDelGen=3
2024-06-19 14:11:10,194 DEBUG [IW] publish sets newSegment delGen=3 seg=_2(8.11.3):c1:[diagnostics={os=Linux, java.vendor=Eclipse Adoptium, java.version=21.0.3, java.vm.version=21.0.3+9-LTS, lucene.version=8.11.3, os.arch=amd64, java.runtime.version=21.0.3+9-LTS, source=flush, os.version=5.15.0-1064-azure, timestamp=1718806270193}]:[attributes={Lucene87StoredFieldsFormat.mode=BEST_SPEED}] :id=9h21l1jsclcghiszkf7l6822a
2024-06-19 14:11:10,194 DEBUG [IFD] now checkpoint "_0(8.11.3):c19:[diagnostics={os=Linux, java.vendor=Eclipse Adoptium, java.version=21.0.3, java.vm.version=21.0.3+9-LTS, lucene.version=8.11.3, os.arch=amd64, java.runtime.version=21.0.3+9-LTS, source=flush, os.version=5.15.0-1064-azure, timestamp=1718805363726}]:[attributes={Lucene87StoredFieldsFormat.mode=BEST_SPEED}] :id=9h21l1jsclcghiszkf7l67yxx _1(8.11.3):c1:[diagnostics={os=Linux, java.vendor=Eclipse Adoptium, java.version=21.0.3, java.vm.version=21.0.3+9-LTS, lucene.version=8.11.3, os.arch=amd64, java.runtime.version=21.0.3+9-LTS, source=flush, os.version=5.15.0-1064-azure, timestamp=1718805921685}]:[attributes={Lucene87StoredFieldsFormat.mode=BEST_SPEED}] :id=9h21l1jsclcghiszkf7l68227 _2(8.11.3):c1:[diagnostics={os=Linux, java.vendor=Eclipse Adoptium, java.version=21.0.3, java.vm.version=21.0.3+9-LTS, lucene.version=8.11.3, os.arch=amd64, java.runtime.version=21.0.3+9-LTS, source=flush, os.version=5.15.0-1064-azure, timestamp=1718806270193}]:[attributes={Lucene87StoredFieldsFormat.mode=BEST_SPEED}] :id=9h21l1jsclcghiszkf7l6822b" [3 segments ; isCommit = false]
2024-06-19 14:11:10,194 DEBUG [IFD] 0 msec to checkpoint
2024-06-19 14:11:10,194 DEBUG [IFD] will delete new file "_2_Lucene84_0.doc"
2024-06-19 14:11:10,194 DEBUG [IFD] will delete new file "_2.nvd"
2024-06-19 14:11:10,194 DEBUG [IFD] will delete new file "_2_Lucene84_0.tim"
2024-06-19 14:11:10,194 DEBUG [IFD] will delete new file "_2.fdm"
2024-06-19 14:11:10,194 DEBUG [IFD] will delete new file "_2_Lucene84_0.pos"
2024-06-19 14:11:10,194 DEBUG [IFD] will delete new file "_2.fdt"
2024-06-19 14:11:10,194 DEBUG [IFD] will delete new file "_2.nvm"
2024-06-19 14:11:10,194 DEBUG [IFD] will delete new file "_2.fnm"
2024-06-19 14:11:10,194 DEBUG [IFD] will delete new file "_2.fdx"
2024-06-19 14:11:10,194 DEBUG [IFD] will delete new file "_2_Lucene84_0.tip"
2024-06-19 14:11:10,194 DEBUG [IFD] will delete new file "_2_Lucene84_0.tmd"
2024-06-19 14:11:10,194 DEBUG [IFD] delete [_2_Lucene84_0.doc, _2.nvd, _2_Lucene84_0.tim, _2.fdm, _2_Lucene84_0.pos, _2.fdt, _2.nvm, _2.fnm, _2.fdx, _2_Lucene84_0.tip, _2_Lucene84_0.tmd]
2024-06-19 14:11:10,195 DEBUG [IW] now apply all deletes for all segments buffered updates bytesUsed=0 reader pool bytesUsed=0
2024-06-19 14:11:10,195 DEBUG [BD] waitApply: no deletes to apply
2024-06-19 14:11:10,195 DEBUG [DW] Alpine-SingleThreadedEventService finishFullFlush success=true
2024-06-19 14:11:10,195 DEBUG [IW] startCommit(): start
2024-06-19 14:11:10,195 DEBUG [IW] startCommit index=_0(8.11.3):c19:[diagnostics={os=Linux, java.vendor=Eclipse Adoptium, java.version=21.0.3, java.vm.version=21.0.3+9-LTS, lucene.version=8.11.3, os.arch=amd64, java.runtime.version=21.0.3+9-LTS, source=flush, os.version=5.15.0-1064-azure, timestamp=1718805363726}]:[attributes={Lucene87StoredFieldsFormat.mode=BEST_SPEED}] :id=9h21l1jsclcghiszkf7l67yxx _1(8.11.3):c1:[diagnostics={os=Linux, java.vendor=Eclipse Adoptium, java.version=21.0.3, java.vm.version=21.0.3+9-LTS, lucene.version=8.11.3, os.arch=amd64, java.runtime.version=21.0.3+9-LTS, source=flush, os.version=5.15.0-1064-azure, timestamp=1718805921685}]:[attributes={Lucene87StoredFieldsFormat.mode=BEST_SPEED}] :id=9h21l1jsclcghiszkf7l68227 _2(8.11.3):c1:[diagnostics={os=Linux, java.vendor=Eclipse Adoptium, java.version=21.0.3, java.vm.version=21.0.3+9-LTS, lucene.version=8.11.3, os.arch=amd64, java.runtime.version=21.0.3+9-LTS, source=flush, os.version=5.15.0-1064-azure, timestamp=1718806270193}]:[attributes={Lucene87StoredFieldsFormat.mode=BEST_SPEED}] :id=9h21l1jsclcghiszkf7l6822b changeCount=12
2024-06-19 14:11:10,207 DEBUG [IW] startCommit: wrote pending segments file "pending_segments_4"
2024-06-19 14:11:10,227 DEBUG [IW] done all syncs: [_1.cfs, _0.cfe, _0.si, _1.cfe, _1.si, _2.si, _0.cfs, _2.cfe, _2.cfs]
2024-06-19 14:11:10,227 DEBUG [IW] commit: pendingCommit != null
2024-06-19 14:11:10,230 DEBUG [IW] commit: done writing segments file "segments_4"
2024-06-19 14:11:10,230 DEBUG [IFD] now checkpoint "_0(8.11.3):c19:[diagnostics={os=Linux, java.vendor=Eclipse Adoptium, java.version=21.0.3, java.vm.version=21.0.3+9-LTS, lucene.version=8.11.3, os.arch=amd64, java.runtime.version=21.0.3+9-LTS, source=flush, os.version=5.15.0-1064-azure, timestamp=1718805363726}]:[attributes={Lucene87StoredFieldsFormat.mode=BEST_SPEED}] :id=9h21l1jsclcghiszkf7l67yxx _1(8.11.3):c1:[diagnostics={os=Linux, java.vendor=Eclipse Adoptium, java.version=21.0.3, java.vm.version=21.0.3+9-LTS, lucene.version=8.11.3, os.arch=amd64, java.runtime.version=21.0.3+9-LTS, source=flush, os.version=5.15.0-1064-azure, timestamp=1718805921685}]:[attributes={Lucene87StoredFieldsFormat.mode=BEST_SPEED}] :id=9h21l1jsclcghiszkf7l68227 _2(8.11.3):c1:[diagnostics={os=Linux, java.vendor=Eclipse Adoptium, java.version=21.0.3, java.vm.version=21.0.3+9-LTS, lucene.version=8.11.3, os.arch=amd64, java.runtime.version=21.0.3+9-LTS, source=flush, os.version=5.15.0-1064-azure, timestamp=1718806270193}]:[attributes={Lucene87StoredFieldsFormat.mode=BEST_SPEED}] :id=9h21l1jsclcghiszkf7l6822b" [3 segments ; isCommit = true]
2024-06-19 14:11:10,230 DEBUG [IFD] deleteCommits: now decRef commit "segments_3"
2024-06-19 14:11:10,230 DEBUG [IFD] delete [segments_3]
2024-06-19 14:11:10,230 DEBUG [IFD] 0 msec to checkpoint
2024-06-19 14:11:10,230 DEBUG [IW] commit: took 39.5 msec
2024-06-19 14:11:10,230 DEBUG [IW] commit: done
2024-06-19 14:11:10,231 DEBUG [MP]   seg=_0(8.11.3):c19:[diagnostics={os=Linux, java.vendor=Eclipse Adoptium, java.version=21.0.3, java.vm.version=21.0.3+9-LTS, lucene.version=8.11.3, os.arch=amd64, java.runtime.version=21.0.3+9-LTS, source=flush, os.version=5.15.0-1064-azure, timestamp=1718805363726}]:[attributes={Lucene87StoredFieldsFormat.mode=BEST_SPEED}] :id=9h21l1jsclcghiszkf7l67yxx size=0.004 MB [floored]
2024-06-19 14:11:10,231 DEBUG [MP]   seg=_1(8.11.3):c1:[diagnostics={os=Linux, java.vendor=Eclipse Adoptium, java.version=21.0.3, java.vm.version=21.0.3+9-LTS, lucene.version=8.11.3, os.arch=amd64, java.runtime.version=21.0.3+9-LTS, source=flush, os.version=5.15.0-1064-azure, timestamp=1718805921685}]:[attributes={Lucene87StoredFieldsFormat.mode=BEST_SPEED}] :id=9h21l1jsclcghiszkf7l68227 size=0.002 MB [floored]
2024-06-19 14:11:10,231 DEBUG [MP]   seg=_2(8.11.3):c1:[diagnostics={os=Linux, java.vendor=Eclipse Adoptium, java.version=21.0.3, java.vm.version=21.0.3+9-LTS, lucene.version=8.11.3, os.arch=amd64, java.runtime.version=21.0.3+9-LTS, source=flush, os.version=5.15.0-1064-azure, timestamp=1718806270193}]:[attributes={Lucene87StoredFieldsFormat.mode=BEST_SPEED}] :id=9h21l1jsclcghiszkf7l6822b size=0.002 MB [floored]
2024-06-19 14:11:10,231 DEBUG [MP] findMerges: 3 segments
2024-06-19 14:11:10,231 DEBUG [MP]   allowedSegmentCount=10 vs count=3 (eligible count=3)
2024-06-19 14:11:10,231 DEBUG [SingleThreadedEventService] Calling onSuccess
2024-06-19 14:11:11,427 DEBUG [HttpClientPool] Stats: [leased: 0; pending: 0; available: 0; max: 200]
2024-06-19 14:11:14,721 DEBUG [HealthServlet] Calling health check: alpine.server.health.checks.DatabaseHealthCheck
...

We are running Dependency Track on an Microsoft Azure managed K8s cluster with PostgreSQL. We are running Dependency Track version v4.11.3 with this Helm chart.

[nscuro]

Can we rule out that this is a service degradation that only occurs after a certain amount of time, i.e. the DT instance has been running for a while?

Or does this happen even immediately after restart?

[JaccoDieleman]

New information: suddenly I get portfolio notifications!

Previously I did my tests by creating a dummy project. Nothing happens (shortly after or long after restart doesn't seem to matter).

Now that I uploaded an SBOM for a dummy project I get notifications for BOM_PROCESSED, BOM_CONSUMED and "Vulnerable Dependency Introduced on Project:". Tomorrow I'll analyse the logs and report my findings here.

[nscuro]

Thanks @JaccoDieleman! I'm happy with every piece of additional info I can get, because I've not been successful in reproducing this so far.

[black-snow]

Cannot repro either. Calling stale.

Do you still have issues w/ the latest version @Kretikus @ag-lls and others?

[JaccoDieleman]

I never got any portfolio notifications until yesterday. No sure what triggered that:

• We recentrly upgraded to the latest version + migrated to PostgreSQL
• I configured SYSTEM scope notifications
• I uploaded a BOM manually through the UI

I went through the logs, but I could not find something that could explain the behavior. Let me know if you @nscuro are interested in the logs.

While testing I created dummy projects. Notifications on project creation is still not working however. Not my biggest concern. What's most important for us: new vulnerabilities in either a new BOM (uploaded through the API) or new vulnerabilities in existing dependencies.

By the way: thanks for the work and the great product! 🤩