Function logs from worker functions sometimes not showing up

[Charles-Gagnon]

Currently only have repros for this using Function Core Tools - working on verifying whether this also happens to deployed functions with logs sent to app insights.

We have a simple function with a SQL trigger that we use in our tests : e.g. https://github.com/Azure/azure-functions-sql-extension/blob/release/trigger/samples/samples-js/ProductsTrigger/index.js

This function just outputs a log message, which the test then watches for to verify that the data the function was sent was correct. We do this by hooking into the OutputDataReceived event for the Process and looking at all the incoming messages.

https://github.com/Azure/azure-functions-sql-extension/blob/release/trigger/test/Integration/SqlTriggerBindingIntegrationTestBase.cs#L127

But occasionally we just never get that log message. We'll get other messages - such as "Function executed" - but the one our function logs just doesn't appear. We wait up to 10 seconds for this after which we give up.

Here's an example of the output logs we see with a missing message. It's a bit verbose - but you can see that there's 5 instances of the Executed 'Functions.ProductsTriggerWithValidation' message, but only 4 SQL Changes: .

[20366] [2023-04-21T20:35:06.068Z] Executing 'Functions.ProductsTriggerWithValidation' (Reason='New change detected on table '[dbo].[Products]' at 2023-04-21T20:35:06.0215457Z.', Id=be0e4ac5-ce83-4923-be7f-a815a9edf666)
[20366] [2023-04-21T20:35:06.098Z] Sending invocation id:be0e4ac5-ce83-4923-be7f-a815a9edf666
[20366] [2023-04-21T20:35:06.104Z] Posting invocation id:be0e4ac5-ce83-4923-be7f-a815a9edf666 on workerId:895f3eb7-94ce-4d7d-a582-d15c6ad252a2
[20366] [2023-04-21T20:35:06.122Z] Writing invocation request invocationId: be0e4ac5-ce83-4923-be7f-a815a9edf666 to workerId: 895f3eb7-94ce-4d7d-a582-d15c6ad252a2
[20366] [2023-04-21T20:35:06.358Z] [channel] received 895f3eb7-94ce-4d7d-a582-d15c6ad252a2: RpcLog
[20366] [2023-04-21T20:35:06.361Z] Received invocation response for invocationId: be0e4ac5-ce83-4923-be7f-a815a9edf666 from workerId: 895f3eb7-94ce-4d7d-a582-d15c6ad252a2
[20366] [2023-04-21T20:35:06.362Z] [channel] received 895f3eb7-94ce-4d7d-a582-d15c6ad252a2: InvocationResponse
[20366] [2023-04-21T20:35:06.368Z] InvocationResponse received for invocation: 'be0e4ac5-ce83-4923-be7f-a815a9edf666'
[20366] [2023-04-21T20:35:06.371Z] SQL Changes: [{"Operation":0,"Item":{"ProductId":1,"Name":"Product 1","Cost":100}},{"Operation":0,"Item":{"ProductId":2,"Name":"Product 2","Cost":200}},{"Operation":0,"Item":{"ProductId":3,"Name":"Product 3","Cost":300}},{"Operation":0,"Item":{"ProductId":4,"Name":"Product 4","Cost":400}},{"Operation":0,"Item":{"ProductId":5,"Name":"Product 5","Cost":500}},{"Operation":0,"Item":{"ProductId":6,"Name":"Product 6","Cost":600}},{"Operation":0,"Item":{"ProductId":7,"Name":"Product 7","Cost":700}},{"Operation":0,"Item":{"ProductId":8,"Name":"Product 8","Cost":800}},{"Operation":0,"Item":{"ProductId":9,"Name":"Product 9","Cost":900}},{"Operation":0,"Item":{"ProductId":10,"Name":"Product 10","Cost":1000}},{"Operation":0,"Item":{"ProductId":11,"Name":"Product 11","Cost":1100}},{"Operation":0,"Item":{"ProductId":12,"Name":"Product 12","Cost":1200}},{"Operation":0,"Item":{"ProductId":13,"Name":"Product 13","Cost":1300}},{"Operation":0,"Item":{"ProductId":14,"Name":"Product 14","Cost":1400}},{"Operation":0,"Item":{"ProductId":15,"Name":"Product 15","Cost":1500}},{"Operation":0,"Item":{"ProductId":16,"Name":"Product 16","Cost":1600}},{"Operation":0,"Item":{"ProductId":17,"Name":"Product 17","Cost":1700}},{"Operation":0,"Item":{"ProductId":18,"Name":"Product 18","Cost":1800}},{"Operation":0,"Item":{"ProductId":19,"Name":"Product 19","Cost":1900}},{"Operation":0,"Item":{"ProductId":20,"Name":"Product 20","Cost":2000}},{"Operation":0,"Item":{"ProductId":21,"Name":"Product 21","Cost":2100}},{"Operation":0,"Item":{"ProductId":22,"Name":"Product 22","Cost":2200}},{"Operation":0,"Item":{"ProductId":23,"Name":"Product 23","Cost":2300}},{"Operation":0,"Item":{"ProductId":24,"Name":"Product 24","Cost":2400}},{"Operation":0,"Item":{"ProductId":25,"Name":"Product 25","Cost":2500}},{"Operation":0,"Item":{"ProductId":26,"Name":"Product 26","Cost":2600}},{"Operation":0,"Item":{"ProductId":27,"Name":"Product 27","Cost":2700}},{"Operation":0,"Item":{"ProductId":28,"Name":"Product 28","Cost":2800}},{"Operation":0,"Item":{"ProductId":29,"Name":"Product 29","Cost":2900}},{"Operation":0,"Item":{"ProductId":30,"Name":"Product 30","Cost":3000}},{"Operation":0,"Item":{"ProductId":31,"Name":"Product 31","Cost":3100}},{"Operation":0,"Item":{"ProductId":32,"Name":"Product 32","Cost":3200}},{"Operation":0,"Item":{"ProductId":33,"Name":"Product 33","Cost":3300}},{"Operation":0,"Item":{"ProductId":34,"Name":"Product 34","Cost":3400}},{"Operation":0,"Item":{"ProductId":35,"Name":"Product 35","Cost":3500}},{"Operation":0,"Item":{"ProductId":36,"Name":"Product 36","Cost":3600}},{"Operation":0,"Item":{"ProductId":37,"Name":"Product 37","Cost":3700}},{"Operation":0,"Item":{"ProductId":38,"Name":"Product 38","Cost":3800}},{"Operation":0,"Item":{"ProductId":39,"Name":"Product 39","Cost":3900}},{"Operation":0,"Item":{"ProductId":40,"Name":"Product 40","Cost":4000}},{"Operation":0,"Item":{"ProductId":41,"Name":"Product 41","Cost":4100}},{"Operation":0,"Item":{"ProductId":42,"Name":"Product 42","Cost":4200}},{"Operation":0,"Item":{"ProductId":43,"Name":"Product 43","Cost":4300}},{"Operation":0,"Item":{"ProductId":44,"Name":"Product 44","Cost":4400}},{"Operation":0,"Item":{"ProductId":45,"Name":"Product 45","Cost":4500}},{"Operation":0,"Item":{"ProductId":46,"Name":"Product 46","Cost":4600}},{"Operation":0,"Item":{"ProductId":47,"Name":"Product 47","Cost":4700}},{"Operation":0,"Item":{"ProductId":48,"Name":"Product 48","Cost":4800}},{"Operation":0,"Item":{"ProductId":49,"Name":"Product 49","Cost":4900}},{"Operation":0,"Item":{"ProductId":50,"Name":"Product 50","Cost":5000}},{"Operation":0,"Item":{"ProductId":51,"Name":"Product 51","Cost":5100}},{"Operation":0,"Item":{"ProductId":52,"Name":"Product 52","Cost":5200}},{"Operation":0,"Item":{"ProductId":53,"Name":"Product 53","Cost":5300}},{"Operation":0,"Item":{"ProductId":54,"Name":"Product 54","Cost":5400}},{"Operation":0,"Item":{"ProductId":55,"Name":"Product 55","Cost":5500}},{"Operation":0,"Item":{"ProductId":56,"Name":"Product 56","Cost":5600}},{"Operation":0,"Item":{"ProductId":57,"Name":"Product 57","Cost":5700}},{"Operation":0,"Item":{"ProductId":58,"Name":"Product 58","Cost":5800}},{"Operation":0,"Item":{"ProductId":59,"Name":"Product 59","Cost":5900}},{"Operation":0,"Item":{"ProductId":60,"Name":"Product 60","Cost":6000}},{"Operation":0,"Item":{"ProductId":61,"Name":"Product 61","Cost":6100}},{"Operation":0,"Item":{"ProductId":62,"Name":"Product 62","Cost":6200}},{"Operation":0,"Item":{"ProductId":63,"Name":"Product 63","Cost":6300}},{"Operation":0,"Item":{"ProductId":64,"Name":"Product 64","Cost":6400}},{"Operation":0,"Item":{"ProductId":65,"Name":"Product 65","Cost":6500}},{"Operation":0,"Item":{"ProductId":66,"Name":"Product 66","Cost":6600}},{"Operation":0,"Item":{"ProductId":67,"Name":"Product 67","Cost":6700}},{"Operation":0,"Item":{"ProductId":68,"Name":"Product 68","Cost":6800}},{"Operation":0,"Item":{"ProductId":69,"Name":"Product 69","Cost":6900}},{"Operation":0,"Item":{"ProductId":70,"Name":"Product 70","Cost":7000}},{"Operation":0,"Item":{"ProductId":71,"Name":"Product 71","Cost":7100}},{"Operation":0,"Item":{"ProductId":72,"Name":"Product 72","Cost":7200}},{"Operation":0,"Item":{"ProductId":73,"Name":"Product 73","Cost":7300}},{"Operation":0,"Item":{"ProductId":74,"Name":"Product 74","Cost":7400}},{"Operation":0,"Item":{"ProductId":75,"Name":"Product 75","Cost":7500}},{"Operation":0,"Item":{"ProductId":76,"Name":"Product 76","Cost":7600}},{"Operation":0,"Item":{"ProductId":77,"Name":"Product 77","Cost":7700}},{"Operation":0,"Item":{"ProductId":78,"Name":"Product 78","Cost":7800}},{"Operation":0,"Item":{"ProductId":79,"Name":"Product 79","Cost":7900}},{"Operation":0,"Item":{"ProductId":80,"Name":"Product 80","Cost":8000}},{"Operation":0,"Item":{"ProductId":81,"Name":"Product 81","Cost":8100}},{"Operation":0,"Item":{"ProductId":82,"Name":"Product 82","Cost":8200}},{"Operation":0,"Item":{"ProductId":83,"Name":"Product 83","Cost":8300}},{"Operation":0,"Item":{"ProductId":84,"Name":"Product 84","Cost":8400}},{"Operation":0,"Item":{"ProductId":85,"Name":"Product 85","Cost":8500}},{"Operation":0,"Item":{"ProductId":86,"Name":"Product 86","Cost":8600}},{"Operation":0,"Item":{"ProductId":87,"Name":"Product 87","Cost":8700}},{"Operation":0,"Item":{"ProductId":88,"Name":"Product 88","Cost":8800}},{"Operation":0,"Item":{"ProductId":89,"Name":"Product 89","Cost":8900}},{"Operation":0,"Item":{"ProductId":90,"Name":"Product 90","Cost":9000}},{"Operation":0,"Item":{"ProductId":91,"Name":"Product 91","Cost":9100}},{"Operation":0,"Item":{"ProductId":92,"Name":"Product 92","Cost":9200}},{"Operation":0,"Item":{"ProductId":93,"Name":"Product 93","Cost":9300}},{"Operation":0,"Item":{"ProductId":94,"Name":"Product 94","Cost":9400}},{"Operation":0,"Item":{"ProductId":95,"Name":"Product 95","Cost":9500}},{"Operation":0,"Item":{"ProductId":96,"Name":"Product 96","Cost":9600}},{"Operation":0,"Item":{"ProductId":97,"Name":"Product 97","Cost":9700}},{"Operation":0,"Item":{"ProductId":98,"Name":"Product 98","Cost":9800}},{"Operation":0,"Item":{"ProductId":99,"Name":"Product 99","Cost":9900}},{"Operation":0,"Item":{"ProductId":100,"Name":"Product 100","Cost":10000}}]
[20366] [2023-04-21T20:35:06.406Z] Executed 'Functions.ProductsTriggerWithValidation' (Succeeded, Id=be0e4ac5-ce83-4923-be7f-a815a9edf666, Duration=368ms)
[20366] [2023-04-21T20:35:06.439Z] No shared memory maps allocated for invocation id: be0e4ac5-ce83-4923-be7f-a815a9edf666 by the host
[20366] [2023-04-21T20:35:07.041Z] Executing 'Functions.ProductsTriggerWithValidation' (Reason='New change detected on table '[dbo].[Products]' at 2023-04-21T20:35:07.0410476Z.', Id=bd6fbac2-5b29-47e7-bbfd-7b589615b572)
[20366] [2023-04-21T20:35:07.042Z] Sending invocation id:bd6fbac2-5b29-47e7-bbfd-7b589615b572
[20366] [2023-04-21T20:35:07.043Z] Posting invocation id:bd6fbac2-5b29-47e7-bbfd-7b589615b572 on workerId:895f3eb7-94ce-4d7d-a582-d15c6ad252a2
[20366] [2023-04-21T20:35:07.043Z] Writing invocation request invocationId: bd6fbac2-5b29-47e7-bbfd-7b589615b572 to workerId: 895f3eb7-94ce-4d7d-a582-d15c6ad252a2
[20366] [2023-04-21T20:35:07.051Z] Received invocation response for invocationId: bd6fbac2-5b29-47e7-bbfd-7b589615b572 from workerId: 895f3eb7-94ce-4d7d-a582-d15c6ad252a2
[20366] [2023-04-21T20:35:07.051Z] [channel] received 895f3eb7-94ce-4d7d-a582-d15c6ad252a2: RpcLog
[20366] [2023-04-21T20:35:07.052Z] SQL Changes: [{"Operation":0,"Item":{"ProductId":101,"Name":"Product 101","Cost":10100}},{"Operation":0,"Item":{"ProductId":102,"Name":"Product 102","Cost":10200}},{"Operation":0,"Item":{"ProductId":103,"Name":"Product 103","Cost":10300}},{"Operation":0,"Item":{"ProductId":104,"Name":"Product 104","Cost":10400}},{"Operation":0,"Item":{"ProductId":105,"Name":"Product 105","Cost":10500}},{"Operation":0,"Item":{"ProductId":106,"Name":"Product 106","Cost":10600}},{"Operation":0,"Item":{"ProductId":107,"Name":"Product 107","Cost":10700}},{"Operation":0,"Item":{"ProductId":108,"Name":"Product 108","Cost":10800}},{"Operation":0,"Item":{"ProductId":109,"Name":"Product 109","Cost":10900}},{"Operation":0,"Item":{"ProductId":110,"Name":"Product 110","Cost":11000}},{"Operation":0,"Item":{"ProductId":111,"Name":"Product 111","Cost":11100}},{"Operation":0,"Item":{"ProductId":112,"Name":"Product 112","Cost":11200}},{"Operation":0,"Item":{"ProductId":113,"Name":"Product 113","Cost":11300}},{"Operation":0,"Item":{"ProductId":114,"Name":"Product 114","Cost":11400}},{"Operation":0,"Item":{"ProductId":115,"Name":"Product 115","Cost":11500}},{"Operation":0,"Item":{"ProductId":116,"Name":"Product 116","Cost":11600}},{"Operation":0,"Item":{"ProductId":117,"Name":"Product 117","Cost":11700}},{"Operation":0,"Item":{"ProductId":118,"Name":"Product 118","Cost":11800}},{"Operation":0,"Item":{"ProductId":119,"Name":"Product 119","Cost":11900}},{"Operation":0,"Item":{"ProductId":120,"Name":"Product 120","Cost":12000}},{"Operation":0,"Item":{"ProductId":121,"Name":"Product 121","Cost":12100}},{"Operation":0,"Item":{"ProductId":122,"Name":"Product 122","Cost":12200}},{"Operation":0,"Item":{"ProductId":123,"Name":"Product 123","Cost":12300}},{"Operation":0,"Item":{"ProductId":124,"Name":"Product 124","Cost":12400}},{"Operation":0,"Item":{"ProductId":125,"Name":"Product 125","Cost":12500}},{"Operation":0,"Item":{"ProductId":126,"Name":"Product 126","Cost":12600}},{"Operation":0,"Item":{"ProductId":127,"Name":"Product 127","Cost":12700}},{"Operation":0,"Item":{"ProductId":128,"Name":"Product 128","Cost":12800}},{"Operation":0,"Item":{"ProductId":129,"Name":"Product 129","Cost":12900}},{"Operation":0,"Item":{"ProductId":130,"Name":"Product 130","Cost":13000}},{"Operation":0,"Item":{"ProductId":131,"Name":"Product 131","Cost":13100}},{"Operation":0,"Item":{"ProductId":132,"Name":"Product 132","Cost":13200}},{"Operation":0,"Item":{"ProductId":133,"Name":"Product 133","Cost":13300}},{"Operation":0,"Item":{"ProductId":134,"Name":"Product 134","Cost":13400}},{"Operation":0,"Item":{"ProductId":135,"Name":"Product 135","Cost":13500}},{"Operation":0,"Item":{"ProductId":136,"Name":"Product 136","Cost":13600}},{"Operation":0,"Item":{"ProductId":137,"Name":"Product 137","Cost":13700}},{"Operation":0,"Item":{"ProductId":138,"Name":"Product 138","Cost":13800}},{"Operation":0,"Item":{"ProductId":139,"Name":"Product 139","Cost":13900}},{"Operation":0,"Item":{"ProductId":140,"Name":"Product 140","Cost":14000}},{"Operation":0,"Item":{"ProductId":141,"Name":"Product 141","Cost":14100}},{"Operation":0,"Item":{"ProductId":142,"Name":"Product 142","Cost":14200}},{"Operation":0,"Item":{"ProductId":143,"Name":"Product 143","Cost":14300}},{"Operation":0,"Item":{"ProductId":144,"Name":"Product 144","Cost":14400}},{"Operation":0,"Item":{"ProductId":145,"Name":"Product 145","Cost":14500}},{"Operation":0,"Item":{"ProductId":146,"Name":"Product 146","Cost":14600}},{"Operation":0,"Item":{"ProductId":147,"Name":"Product 147","Cost":14700}},{"Operation":0,"Item":{"ProductId":148,"Name":"Product 148","Cost":14800}},{"Operation":0,"Item":{"ProductId":149,"Name":"Product 149","Cost":14900}},{"Operation":0,"Item":{"ProductId":150,"Name":"Product 150","Cost":15000}},{"Operation":0,"Item":{"ProductId":151,"Name":"Product 151","Cost":15100}},{"Operation":0,"Item":{"ProductId":152,"Name":"Product 152","Cost":15200}},{"Operation":0,"Item":{"ProductId":153,"Name":"Product 153","Cost":15300}},{"Operation":0,"Item":{"ProductId":154,"Name":"Product 154","Cost":15400}},{"Operation":0,"Item":{"ProductId":155,"Name":"Product 155","Cost":15500}},{"Operation":0,"Item":{"ProductId":156,"Name":"Product 156","Cost":15600}},{"Operation":0,"Item":{"ProductId":157,"Name":"Product 157","Cost":15700}},{"Operation":0,"Item":{"ProductId":158,"Name":"Product 158","Cost":15800}},{"Operation":0,"Item":{"ProductId":159,"Name":"Product 159","Cost":15900}},{"Operation":0,"Item":{"ProductId":160,"Name":"Product 160","Cost":16000}},{"Operation":0,"Item":{"ProductId":161,"Name":"Product 161","Cost":16100}},{"Operation":0,"Item":{"ProductId":162,"Name":"Product 162","Cost":16200}},{"Operation":0,"Item":{"ProductId":163,"Name":"Product 163","Cost":16300}},{"Operation":0,"Item":{"ProductId":164,"Name":"Product 164","Cost":16400}},{"Operation":0,"Item":{"ProductId":165,"Name":"Product 165","Cost":16500}},{"Operation":0,"Item":{"ProductId":166,"Name":"Product 166","Cost":16600}},{"Operation":0,"Item":{"ProductId":167,"Name":"Product 167","Cost":16700}},{"Operation":0,"Item":{"ProductId":168,"Name":"Product 168","Cost":16800}},{"Operation":0,"Item":{"ProductId":169,"Name":"Product 169","Cost":16900}},{"Operation":0,"Item":{"ProductId":170,"Name":"Product 170","Cost":17000}},{"Operation":0,"Item":{"ProductId":171,"Name":"Product 171","Cost":17100}},{"Operation":0,"Item":{"ProductId":172,"Name":"Product 172","Cost":17200}},{"Operation":0,"Item":{"ProductId":173,"Name":"Product 173","Cost":17300}},{"Operation":0,"Item":{"ProductId":174,"Name":"Product 174","Cost":17400}},{"Operation":0,"Item":{"ProductId":175,"Name":"Product 175","Cost":17500}},{"Operation":0,"Item":{"ProductId":176,"Name":"Product 176","Cost":17600}},{"Operation":0,"Item":{"ProductId":177,"Name":"Product 177","Cost":17700}},{"Operation":0,"Item":{"ProductId":178,"Name":"Product 178","Cost":17800}},{"Operation":0,"Item":{"ProductId":179,"Name":"Product 179","Cost":17900}},{"Operation":0,"Item":{"ProductId":180,"Name":"Product 180","Cost":18000}},{"Operation":0,"Item":{"ProductId":181,"Name":"Product 181","Cost":18100}},{"Operation":0,"Item":{"ProductId":182,"Name":"Product 182","Cost":18200}},{"Operation":0,"Item":{"ProductId":183,"Name":"Product 183","Cost":18300}},{"Operation":0,"Item":{"ProductId":184,"Name":"Product 184","Cost":18400}},{"Operation":0,"Item":{"ProductId":185,"Name":"Product 185","Cost":18500}},{"Operation":0,"Item":{"ProductId":186,"Name":"Product 186","Cost":18600}},{"Operation":0,"Item":{"ProductId":187,"Name":"Product 187","Cost":18700}},{"Operation":0,"Item":{"ProductId":188,"Name":"Product 188","Cost":18800}},{"Operation":0,"Item":{"ProductId":189,"Name":"Product 189","Cost":18900}},{"Operation":0,"Item":{"ProductId":190,"Name":"Product 190","Cost":19000}},{"Operation":0,"Item":{"ProductId":191,"Name":"Product 191","Cost":19100}},{"Operation":0,"Item":{"ProductId":192,"Name":"Product 192","Cost":19200}},{"Operation":0,"Item":{"ProductId":193,"Name":"Product 193","Cost":19300}},{"Operation":0,"Item":{"ProductId":194,"Name":"Product 194","Cost":19400}},{"Operation":0,"Item":{"ProductId":195,"Name":"Product 195","Cost":19500}},{"Operation":0,"Item":{"ProductId":196,"Name":"Product 196","Cost":19600}},{"Operation":0,"Item":{"ProductId":197,"Name":"Product 197","Cost":19700}},{"Operation":0,"Item":{"ProductId":198,"Name":"Product 198","Cost":19800}},{"Operation":0,"Item":{"ProductId":199,"Name":"Product 199","Cost":19900}},{"Operation":0,"Item":{"ProductId":200,"Name":"Product 200","Cost":20000}}]
[20366] [2023-04-21T20:35:07.054Z] [channel] received 895f3eb7-94ce-4d7d-a582-d15c6ad252a2: InvocationResponse
[20366] [2023-04-21T20:35:07.054Z] InvocationResponse received for invocation: 'bd6fbac2-5b29-47e7-bbfd-7b589615b572'
[20366] [2023-04-21T20:35:07.055Z] Executed 'Functions.ProductsTriggerWithValidation' (Succeeded, Id=bd6fbac2-5b29-47e7-bbfd-7b589615b572, Duration=14ms)
[20366] [2023-04-21T20:35:07.061Z] No shared memory maps allocated for invocation id: bd6fbac2-5b29-47e7-bbfd-7b589615b572 by the host
[20366] [2023-04-21T20:35:07.718Z] Executing 'Functions.ProductsTriggerWithValidation' (Reason='New change detected on table '[dbo].[Products]' at 2023-04-21T20:35:07.7181827Z.', Id=98a4a2a3-1580-4f44-96dc-45a0580b59e3)
[20366] [2023-04-21T20:35:07.718Z] Sending invocation id:98a4a2a3-1580-4f44-96dc-45a0580b59e3
[20366] [2023-04-21T20:35:07.718Z] Posting invocation id:98a4a2a3-1580-4f44-96dc-45a0580b59e3 on workerId:895f3eb7-94ce-4d7d-a582-d15c6ad252a2
[20366] [2023-04-21T20:35:07.719Z] Writing invocation request invocationId: 98a4a2a3-1580-4f44-96dc-45a0580b59e3 to workerId: 895f3eb7-94ce-4d7d-a582-d15c6ad252a2
[20366] [2023-04-21T20:35:07.722Z] Received invocation response for invocationId: 98a4a2a3-1580-4f44-96dc-45a0580b59e3 from workerId: 895f3eb7-94ce-4d7d-a582-d15c6ad252a2
[20366] [2023-04-21T20:35:07.722Z] [channel] received 895f3eb7-94ce-4d7d-a582-d15c6ad252a2: RpcLog
[20366] [2023-04-21T20:35:07.722Z] [channel] received 895f3eb7-94ce-4d7d-a582-d15c6ad252a2: InvocationResponse
[20366] [2023-04-21T20:35:07.722Z] InvocationResponse received for invocation: '98a4a2a3-1580-4f44-96dc-45a0580b59e3'
[20366] [2023-04-21T20:35:07.722Z] SQL Changes: [{"Operation":0,"Item":{"ProductId":201,"Name":"Product 201","Cost":20100}},{"Operation":0,"Item":{"ProductId":202,"Name":"Product 202","Cost":20200}},{"Operation":0,"Item":{"ProductId":203,"Name":"Product 203","Cost":20300}},{"Operation":0,"Item":{"ProductId":204,"Name":"Product 204","Cost":20400}},{"Operation":0,"Item":{"ProductId":205,"Name":"Product 205","Cost":20500}},{"Operation":0,"Item":{"ProductId":206,"Name":"Product 206","Cost":20600}},{"Operation":0,"Item":{"ProductId":207,"Name":"Product 207","Cost":20700}},{"Operation":0,"Item":{"ProductId":208,"Name":"Product 208","Cost":20800}},{"Operation":0,"Item":{"ProductId":209,"Name":"Product 209","Cost":20900}},{"Operation":0,"Item":{"ProductId":210,"Name":"Product 210","Cost":21000}},{"Operation":0,"Item":{"ProductId":211,"Name":"Product 211","Cost":21100}},{"Operation":0,"Item":{"ProductId":212,"Name":"Product 212","Cost":21200}},{"Operation":0,"Item":{"ProductId":213,"Name":"Product 213","Cost":21300}},{"Operation":0,"Item":{"ProductId":214,"Name":"Product 214","Cost":21400}},{"Operation":0,"Item":{"ProductId":215,"Name":"Product 215","Cost":21500}},{"Operation":0,"Item":{"ProductId":216,"Name":"Product 216","Cost":21600}},{"Operation":0,"Item":{"ProductId":217,"Name":"Product 217","Cost":21700}},{"Operation":0,"Item":{"ProductId":218,"Name":"Product 218","Cost":21800}},{"Operation":0,"Item":{"ProductId":219,"Name":"Product 219","Cost":21900}},{"Operation":0,"Item":{"ProductId":220,"Name":"Product 220","Cost":22000}},{"Operation":0,"Item":{"ProductId":221,"Name":"Product 221","Cost":22100}},{"Operation":0,"Item":{"ProductId":222,"Name":"Product 222","Cost":22200}},{"Operation":0,"Item":{"ProductId":223,"Name":"Product 223","Cost":22300}},{"Operation":0,"Item":{"ProductId":224,"Name":"Product 224","Cost":22400}},{"Operation":0,"Item":{"ProductId":225,"Name":"Product 225","Cost":22500}},{"Operation":0,"Item":{"ProductId":226,"Name":"Product 226","Cost":22600}},{"Operation":0,"Item":{"ProductId":227,"Name":"Product 227","Cost":22700}},{"Operation":0,"Item":{"ProductId":228,"Name":"Product 228","Cost":22800}},{"Operation":0,"Item":{"ProductId":229,"Name":"Product 229","Cost":22900}},{"Operation":0,"Item":{"ProductId":230,"Name":"Product 230","Cost":23000}},{"Operation":0,"Item":{"ProductId":231,"Name":"Product 231","Cost":23100}},{"Operation":0,"Item":{"ProductId":232,"Name":"Product 232","Cost":23200}},{"Operation":0,"Item":{"ProductId":233,"Name":"Product 233","Cost":23300}},{"Operation":0,"Item":{"ProductId":234,"Name":"Product 234","Cost":23400}},{"Operation":0,"Item":{"ProductId":235,"Name":"Product 235","Cost":23500}},{"Operation":0,"Item":{"ProductId":236,"Name":"Product 236","Cost":23600}},{"Operation":0,"Item":{"ProductId":237,"Name":"Product 237","Cost":23700}},{"Operation":0,"Item":{"ProductId":238,"Name":"Product 238","Cost":23800}},{"Operation":0,"Item":{"ProductId":239,"Name":"Product 239","Cost":23900}},{"Operation":0,"Item":{"ProductId":240,"Name":"Product 240","Cost":24000}},{"Operation":0,"Item":{"ProductId":241,"Name":"Product 241","Cost":24100}},{"Operation":0,"Item":{"ProductId":242,"Name":"Product 242","Cost":24200}},{"Operation":0,"Item":{"ProductId":243,"Name":"Product 243","Cost":24300}},{"Operation":0,"Item":{"ProductId":244,"Name":"Product 244","Cost":24400}},{"Operation":0,"Item":{"ProductId":245,"Name":"Product 245","Cost":24500}},{"Operation":0,"Item":{"ProductId":246,"Name":"Product 246","Cost":24600}},{"Operation":0,"Item":{"ProductId":247,"Name":"Product 247","Cost":24700}},{"Operation":0,"Item":{"ProductId":248,"Name":"Product 248","Cost":24800}},{"Operation":0,"Item":{"ProductId":249,"Name":"Product 249","Cost":24900}},{"Operation":0,"Item":{"ProductId":250,"Name":"Product 250","Cost":25000}},{"Operation":0,"Item":{"ProductId":251,"Name":"Product 251","Cost":25100}},{"Operation":0,"Item":{"ProductId":252,"Name":"Product 252","Cost":25200}},{"Operation":0,"Item":{"ProductId":253,"Name":"Product 253","Cost":25300}},{"Operation":0,"Item":{"ProductId":254,"Name":"Product 254","Cost":25400}},{"Operation":0,"Item":{"ProductId":255,"Name":"Product 255","Cost":25500}},{"Operation":0,"Item":{"ProductId":256,"Name":"Product 256","Cost":25600}},{"Operation":0,"Item":{"ProductId":257,"Name":"Product 257","Cost":25700}},{"Operation":0,"Item":{"ProductId":258,"Name":"Product 258","Cost":25800}},{"Operation":0,"Item":{"ProductId":259,"Name":"Product 259","Cost":25900}},{"Operation":0,"Item":{"ProductId":260,"Name":"Product 260","Cost":26000}},{"Operation":0,"Item":{"ProductId":261,"Name":"Product 261","Cost":26100}},{"Operation":0,"Item":{"ProductId":262,"Name":"Product 262","Cost":26200}},{"Operation":0,"Item":{"ProductId":263,"Name":"Product 263","Cost":26300}},{"Operation":0,"Item":{"ProductId":264,"Name":"Product 264","Cost":26400}},{"Operation":0,"Item":{"ProductId":265,"Name":"Product 265","Cost":26500}},{"Operation":0,"Item":{"ProductId":266,"Name":"Product 266","Cost":26600}},{"Operation":0,"Item":{"ProductId":267,"Name":"Product 267","Cost":26700}},{"Operation":0,"Item":{"ProductId":268,"Name":"Product 268","Cost":26800}},{"Operation":0,"Item":{"ProductId":269,"Name":"Product 269","Cost":26900}},{"Operation":0,"Item":{"ProductId":270,"Name":"Product 270","Cost":27000}},{"Operation":0,"Item":{"ProductId":271,"Name":"Product 271","Cost":27100}},{"Operation":0,"Item":{"ProductId":272,"Name":"Product 272","Cost":27200}},{"Operation":0,"Item":{"ProductId":273,"Name":"Product 273","Cost":27300}},{"Operation":0,"Item":{"ProductId":274,"Name":"Product 274","Cost":27400}},{"Operation":0,"Item":{"ProductId":275,"Name":"Product 275","Cost":27500}},{"Operation":0,"Item":{"ProductId":276,"Name":"Product 276","Cost":27600}},{"Operation":0,"Item":{"ProductId":277,"Name":"Product 277","Cost":27700}},{"Operation":0,"Item":{"ProductId":278,"Name":"Product 278","Cost":27800}},{"Operation":0,"Item":{"ProductId":279,"Name":"Product 279","Cost":27900}},{"Operation":0,"Item":{"ProductId":280,"Name":"Product 280","Cost":28000}},{"Operation":0,"Item":{"ProductId":281,"Name":"Product 281","Cost":28100}},{"Operation":0,"Item":{"ProductId":282,"Name":"Product 282","Cost":28200}},{"Operation":0,"Item":{"ProductId":283,"Name":"Product 283","Cost":28300}},{"Operation":0,"Item":{"ProductId":284,"Name":"Product 284","Cost":28400}},{"Operation":0,"Item":{"ProductId":285,"Name":"Product 285","Cost":28500}},{"Operation":0,"Item":{"ProductId":286,"Name":"Product 286","Cost":28600}},{"Operation":0,"Item":{"ProductId":287,"Name":"Product 287","Cost":28700}},{"Operation":0,"Item":{"ProductId":288,"Name":"Product 288","Cost":28800}},{"Operation":0,"Item":{"ProductId":289,"Name":"Product 289","Cost":28900}},{"Operation":0,"Item":{"ProductId":290,"Name":"Product 290","Cost":29000}},{"Operation":0,"Item":{"ProductId":291,"Name":"Product 291","Cost":29100}},{"Operation":0,"Item":{"ProductId":292,"Name":"Product 292","Cost":29200}},{"Operation":0,"Item":{"ProductId":293,"Name":"Product 293","Cost":29300}},{"Operation":0,"Item":{"ProductId":294,"Name":"Product 294","Cost":29400}},{"Operation":0,"Item":{"ProductId":295,"Name":"Product 295","Cost":29500}},{"Operation":0,"Item":{"ProductId":296,"Name":"Product 296","Cost":29600}},{"Operation":0,"Item":{"ProductId":297,"Name":"Product 297","Cost":29700}},{"Operation":0,"Item":{"ProductId":298,"Name":"Product 298","Cost":29800}},{"Operation":0,"Item":{"ProductId":299,"Name":"Product 299","Cost":29900}},{"Operation":0,"Item":{"ProductId":300,"Name":"Product 300","Cost":30000}}]
[20366] [2023-04-21T20:35:07.723Z] Executed 'Functions.ProductsTriggerWithValidation' (Succeeded, Id=98a4a2a3-1580-4f44-96dc-45a0580b59e3, Duration=4ms)
[20366] [2023-04-21T20:35:07.725Z] No shared memory maps allocated for invocation id: 98a4a2a3-1580-4f44-96dc-45a0580b59e3 by the host
[20366] [2023-04-21T20:35:08.413Z] Executing 'Functions.ProductsTriggerWithValidation' (Reason='New change detected on table '[dbo].[Products]' at 2023-04-21T20:35:08.4135258Z.', Id=1bec5c13-0023-4406-802e-83328de23162)
[20366] [2023-04-21T20:35:08.414Z] Sending invocation id:1bec5c13-0023-4406-802e-83328de23162
[20366] [2023-04-21T20:35:08.414Z] Posting invocation id:1bec5c13-0023-4406-802e-83328de23162 on workerId:895f3eb7-94ce-4d7d-a582-d15c6ad252a2
[20366] [2023-04-21T20:35:08.414Z] Writing invocation request invocationId: 1bec5c13-0023-4406-802e-83328de23162 to workerId: 895f3eb7-94ce-4d7d-a582-d15c6ad252a2
[20366] [2023-04-21T20:35:08.416Z] Received invocation response for invocationId: 1bec5c13-0023-4406-802e-83328de23162 from workerId: 895f3eb7-94ce-4d7d-a582-d15c6ad252a2
[20366] [2023-04-21T20:35:08.416Z] [channel] received 895f3eb7-94ce-4d7d-a582-d15c6ad252a2: RpcLog
[20366] [2023-04-21T20:35:08.416Z] [channel] received 895f3eb7-94ce-4d7d-a582-d15c6ad252a2: InvocationResponse
[20366] [2023-04-21T20:35:08.416Z] InvocationResponse received for invocation: '1bec5c13-0023-4406-802e-83328de23162'
[20366] [2023-04-21T20:35:08.416Z] Executed 'Functions.ProductsTriggerWithValidation' (Succeeded, Id=1bec5c13-0023-4406-802e-83328de23162, Duration=3ms)
[20366] [2023-04-21T20:35:08.431Z] No shared memory maps allocated for invocation id: 1bec5c13-0023-4406-802e-83328de23162 by the host
[20366] [2023-04-21T20:35:09.175Z] Executing 'Functions.ProductsTriggerWithValidation' (Reason='New change detected on table '[dbo].[Products]' at 2023-04-21T20:35:09.1748647Z.', Id=19aa858b-1ec2-4311-8232-3e67fd75dc68)
[20366] [2023-04-21T20:35:09.175Z] Sending invocation id:19aa858b-1ec2-4311-8232-3e67fd75dc68
[20366] [2023-04-21T20:35:09.175Z] Posting invocation id:19aa858b-1ec2-4311-8232-3e67fd75dc68 on workerId:895f3eb7-94ce-4d7d-a582-d15c6ad252a2
[20366] [2023-04-21T20:35:09.175Z] Writing invocation request invocationId: 19aa858b-1ec2-4311-8232-3e67fd75dc68 to workerId: 895f3eb7-94ce-4d7d-a582-d15c6ad252a2
[20366] [2023-04-21T20:35:09.177Z] Received invocation response for invocationId: 19aa858b-1ec2-4311-8232-3e67fd75dc68 from workerId: 895f3eb7-94ce-4d7d-a582-d15c6ad252a2
[20366] [2023-04-21T20:35:09.177Z] [channel] received 895f3eb7-94ce-4d7d-a582-d15c6ad252a2: RpcLog
[20366] [2023-04-21T20:35:09.177Z] [channel] received 895f3eb7-94ce-4d7d-a582-d15c6ad252a2: InvocationResponse
[20366] [2023-04-21T20:35:09.177Z] SQL Changes: [{"Operation":0,"Item":{"ProductId":401,"Name":"Product 401","Cost":40100}},{"Operation":0,"Item":{"ProductId":402,"Name":"Product 402","Cost":40200}},{"Operation":0,"Item":{"ProductId":403,"Name":"Product 403","Cost":40300}},{"Operation":0,"Item":{"ProductId":404,"Name":"Product 404","Cost":40400}},{"Operation":0,"Item":{"ProductId":405,"Name":"Product 405","Cost":40500}},{"Operation":0,"Item":{"ProductId":406,"Name":"Product 406","Cost":40600}},{"Operation":0,"Item":{"ProductId":407,"Name":"Product 407","Cost":40700}},{"Operation":0,"Item":{"ProductId":408,"Name":"Product 408","Cost":40800}},{"Operation":0,"Item":{"ProductId":409,"Name":"Product 409","Cost":40900}},{"Operation":0,"Item":{"ProductId":410,"Name":"Product 410","Cost":41000}},{"Operation":0,"Item":{"ProductId":411,"Name":"Product 411","Cost":41100}},{"Operation":0,"Item":{"ProductId":412,"Name":"Product 412","Cost":41200}},{"Operation":0,"Item":{"ProductId":413,"Name":"Product 413","Cost":41300}},{"Operation":0,"Item":{"ProductId":414,"Name":"Product 414","Cost":41400}},{"Operation":0,"Item":{"ProductId":415,"Name":"Product 415","Cost":41500}},{"Operation":0,"Item":{"ProductId":416,"Name":"Product 416","Cost":41600}},{"Operation":0,"Item":{"ProductId":417,"Name":"Product 417","Cost":41700}},{"Operation":0,"Item":{"ProductId":418,"Name":"Product 418","Cost":41800}},{"Operation":0,"Item":{"ProductId":419,"Name":"Product 419","Cost":41900}},{"Operation":0,"Item":{"ProductId":420,"Name":"Product 420","Cost":42000}},{"Operation":0,"Item":{"ProductId":421,"Name":"Product 421","Cost":42100}},{"Operation":0,"Item":{"ProductId":422,"Name":"Product 422","Cost":42200}},{"Operation":0,"Item":{"ProductId":423,"Name":"Product 423","Cost":42300}},{"Operation":0,"Item":{"ProductId":424,"Name":"Product 424","Cost":42400}},{"Operation":0,"Item":{"ProductId":425,"Name":"Product 425","Cost":42500}},{"Operation":0,"Item":{"ProductId":426,"Name":"Product 426","Cost":42600}},{"Operation":0,"Item":{"ProductId":427,"Name":"Product 427","Cost":42700}},{"Operation":0,"Item":{"ProductId":428,"Name":"Product 428","Cost":42800}},{"Operation":0,"Item":{"ProductId":429,"Name":"Product 429","Cost":42900}},{"Operation":0,"Item":{"ProductId":430,"Name":"Product 430","Cost":43000}},{"Operation":0,"Item":{"ProductId":431,"Name":"Product 431","Cost":43100}},{"Operation":0,"Item":{"ProductId":432,"Name":"Product 432","Cost":43200}},{"Operation":0,"Item":{"ProductId":433,"Name":"Product 433","Cost":43300}},{"Operation":0,"Item":{"ProductId":434,"Name":"Product 434","Cost":43400}},{"Operation":0,"Item":{"ProductId":435,"Name":"Product 435","Cost":43500}},{"Operation":0,"Item":{"ProductId":436,"Name":"Product 436","Cost":43600}},{"Operation":0,"Item":{"ProductId":437,"Name":"Product 437","Cost":43700}},{"Operation":0,"Item":{"ProductId":438,"Name":"Product 438","Cost":43800}},{"Operation":0,"Item":{"ProductId":439,"Name":"Product 439","Cost":43900}},{"Operation":0,"Item":{"ProductId":440,"Name":"Product 440","Cost":44000}},{"Operation":0,"Item":{"ProductId":441,"Name":"Product 441","Cost":44100}},{"Operation":0,"Item":{"ProductId":442,"Name":"Product 442","Cost":44200}},{"Operation":0,"Item":{"ProductId":443,"Name":"Product 443","Cost":44300}},{"Operation":0,"Item":{"ProductId":444,"Name":"Product 444","Cost":44400}},{"Operation":0,"Item":{"ProductId":445,"Name":"Product 445","Cost":44500}},{"Operation":0,"Item":{"ProductId":446,"Name":"Product 446","Cost":44600}},{"Operation":0,"Item":{"ProductId":447,"Name":"Product 447","Cost":44700}},{"Operation":0,"Item":{"ProductId":448,"Name":"Product 448","Cost":44800}},{"Operation":0,"Item":{"ProductId":449,"Name":"Product 449","Cost":44900}},{"Operation":0,"Item":{"ProductId":450,"Name":"Product 450","Cost":45000}},{"Operation":0,"Item":{"ProductId":451,"Name":"Product 451","Cost":45100}},{"Operation":0,"Item":{"ProductId":452,"Name":"Product 452","Cost":45200}},{"Operation":0,"Item":{"ProductId":453,"Name":"Product 453","Cost":45300}},{"Operation":0,"Item":{"ProductId":454,"Name":"Product 454","Cost":45400}},{"Operation":0,"Item":{"ProductId":455,"Name":"Product 455","Cost":45500}},{"Operation":0,"Item":{"ProductId":456,"Name":"Product 456","Cost":45600}},{"Operation":0,"Item":{"ProductId":457,"Name":"Product 457","Cost":45700}},{"Operation":0,"Item":{"ProductId":458,"Name":"Product 458","Cost":45800}},{"Operation":0,"Item":{"ProductId":459,"Name":"Product 459","Cost":45900}},{"Operation":0,"Item":{"ProductId":460,"Name":"Product 460","Cost":46000}},{"Operation":0,"Item":{"ProductId":461,"Name":"Product 461","Cost":46100}},{"Operation":0,"Item":{"ProductId":462,"Name":"Product 462","Cost":46200}},{"Operation":0,"Item":{"ProductId":463,"Name":"Product 463","Cost":46300}},{"Operation":0,"Item":{"ProductId":464,"Name":"Product 464","Cost":46400}},{"Operation":0,"Item":{"ProductId":465,"Name":"Product 465","Cost":46500}},{"Operation":0,"Item":{"ProductId":466,"Name":"Product 466","Cost":46600}},{"Operation":0,"Item":{"ProductId":467,"Name":"Product 467","Cost":46700}},{"Operation":0,"Item":{"ProductId":468,"Name":"Product 468","Cost":46800}},{"Operation":0,"Item":{"ProductId":469,"Name":"Product 469","Cost":46900}},{"Operation":0,"Item":{"ProductId":470,"Name":"Product 470","Cost":47000}},{"Operation":0,"Item":{"ProductId":471,"Name":"Product 471","Cost":47100}},{"Operation":0,"Item":{"ProductId":472,"Name":"Product 472","Cost":47200}},{"Operation":0,"Item":{"ProductId":473,"Name":"Product 473","Cost":47300}},{"Operation":0,"Item":{"ProductId":474,"Name":"Product 474","Cost":47400}},{"Operation":0,"Item":{"ProductId":475,"Name":"Product 475","Cost":47500}},{"Operation":0,"Item":{"ProductId":476,"Name":"Product 476","Cost":47600}},{"Operation":0,"Item":{"ProductId":477,"Name":"Product 477","Cost":47700}},{"Operation":0,"Item":{"ProductId":478,"Name":"Product 478","Cost":47800}},{"Operation":0,"Item":{"ProductId":479,"Name":"Product 479","Cost":47900}},{"Operation":0,"Item":{"ProductId":480,"Name":"Product 480","Cost":48000}},{"Operation":0,"Item":{"ProductId":481,"Name":"Product 481","Cost":48100}},{"Operation":0,"Item":{"ProductId":482,"Name":"Product 482","Cost":48200}},{"Operation":0,"Item":{"ProductId":483,"Name":"Product 483","Cost":48300}},{"Operation":0,"Item":{"ProductId":484,"Name":"Product 484","Cost":48400}},{"Operation":0,"Item":{"ProductId":485,"Name":"Product 485","Cost":48500}},{"Operation":0,"Item":{"ProductId":486,"Name":"Product 486","Cost":48600}},{"Operation":0,"Item":{"ProductId":487,"Name":"Product 487","Cost":48700}},{"Operation":0,"Item":{"ProductId":488,"Name":"Product 488","Cost":48800}},{"Operation":0,"Item":{"ProductId":489,"Name":"Product 489","Cost":48900}},{"Operation":0,"Item":{"ProductId":490,"Name":"Product 490","Cost":49000}},{"Operation":0,"Item":{"ProductId":491,"Name":"Product 491","Cost":49100}},{"Operation":0,"Item":{"ProductId":492,"Name":"Product 492","Cost":49200}},{"Operation":0,"Item":{"ProductId":493,"Name":"Product 493","Cost":49300}},{"Operation":0,"Item":{"ProductId":494,"Name":"Product 494","Cost":49400}},{"Operation":0,"Item":{"ProductId":495,"Name":"Product 495","Cost":49500}},{"Operation":0,"Item":{"ProductId":496,"Name":"Product 496","Cost":49600}},{"Operation":0,"Item":{"ProductId":497,"Name":"Product 497","Cost":49700}},{"Operation":0,"Item":{"ProductId":498,"Name":"Product 498","Cost":49800}},{"Operation":0,"Item":{"ProductId":499,"Name":"Product 499","Cost":49900}},{"Operation":0,"Item":{"ProductId":500,"Name":"Product 500","Cost":50000}}]
[20366] [2023-04-21T20:35:09.177Z] InvocationResponse received for invocation: '19aa858b-1ec2-4311-8232-3e67fd75dc68'
[20366] [2023-04-21T20:35:09.178Z] Executed 'Functions.ProductsTriggerWithValidation' (Succeeded, Id=19aa858b-1ec2-4311-8232-3e67fd75dc68, Duration=3ms)
[20366] [2023-04-21T20:35:09.189Z] No shared memory maps allocated for invocation id: 19aa858b-1ec2-4311-8232-3e67fd75dc68 by the host

We also see 5 pairs of these messages :

[20366] [2023-04-21T20:35:09.177Z] [channel] received 895f3eb7-94ce-4d7d-a582-d15c6ad252a2: RpcLog
[20366] [2023-04-21T20:35:09.177Z] [channel] received 895f3eb7-94ce-4d7d-a582-d15c6ad252a2: InvocationResponse

which seem to imply that the host did get the log message, but something happened to it after that.

[satvu]

@RohitRanjanMS Since you were assigned, checking to see if you are picking up this issue and/or actively working on it.

[satvu]

Discussed offline, @RohitRanjanMS is handling this issue.

[pjrharley]

I believe we may also be encountering this issue, or something similar at least.

We have a function that, in addition to the default logs produced by the worker, makes the following logs:

• function started
• successfully made an http request
• function completed

We have a dashboard using these logs and have found that we were consistently showing fewer "function completed" logs than expected (up to 1% of them are missing).

I've tried to reproduced this locally and not managed to have the logs missing entirely, but what I have found is the following. Where I might have expected to see this:

[2023-06-14T15:57:31.722Z] Executing 'Functions.myFunction' (Reason='This function was programmatically called via the host APIs.', Id=eaf11d4a-1722-475f-9818-8965d90b37c1)
[2023-06-14T15:57:31.725Z] {"name":"handler.received","invocationId":"eaf11d4a-1722-475f-9818-8965d90b37c1"}
[2023-06-14T15:57:31.728Z] {"name":"http.request.end.success","invocationId":"eaf11d4a-1722-475f-9818-8965d90b37c1"}
[2023-06-14T15:57:31.728Z] {"name":"handler.completed","invocationId":"eaf11d4a-1722-475f-9818-8965d90b37c1"}
[2023-06-14T15:57:31.728Z] Executed 'Functions.myFunction' (Succeeded, Id=eaf11d4a-1722-475f-9818-8965d90b37c1, Duration=6ms) 

Occasionally they appear as follows instead:

[2023-06-14T15:57:31.722Z] Executing 'Functions.myFunction' (Reason='This function was programmatically called via the host APIs.', Id=eaf11d4a-1722-475f-9818-8965d90b37c1)
[2023-06-14T15:57:31.725Z] {"name":"handler.received","invocationId":"eaf11d4a-1722-475f-9818-8965d90b37c1"}
[2023-06-14T15:57:31.728Z] {"name":"http.request.end.success","invocationId":"eaf11d4a-1722-475f-9818-8965d90b37c1"}[2023-06-14T15:57:31.728Z] {"name":"handler.completed","invocationId":"eaf11d4a-1722-475f-9818-8965d90b37c1"}

[2023-06-14T15:57:31.728Z] Executed 'Functions.myFunction' (Succeeded, Id=eaf11d4a-1722-475f-9818-8965d90b37c1, Duration=6ms)

I'm not sure whether this is just something that might happen when running locally or really representative of what would happen on the actual function. I'm also not sure whether this would lead to the log appended onto the single line to be lost altogether - I'd expect to still be able to find it all appended together as one log statement, but I can't.

Does this seem like it could be related? Could you suggest any further debugging steps I could take?

Version info: locally using azure func core tools 4.0.5198, which seems to depend on 4.21.1
On Azure, runtime version: 4.21.3.20740

[andystaples]

Working on this with @RohitRanjanMS, we believe we have identified a race condition in the host that would explain this issue, escalating to host team to confirm.

[andystaples]

Race condition is as follows:
Log() method in GrpcWorkerChannel.cs depends on the ScriptInvocationContext being present in _executingInvocations, here: https://github.com/Azure/azure-functions-host/blob/8caea0f53dba65ea6651d2e0a4fd766cbd9786ba/src/WebJobs.Script.Grpc/Channel/GrpcWorkerChannel.cs#L1063C1-L1064C1

However, InvokeResponse removes the context from this collection simultaneously, here:

azure-functions-host/src/WebJobs.Script.Grpc/Channel/GrpcWorkerChannel.cs

Line 962 in 8caea0f

if (_executingInvocations.TryRemove(invokeResponse.InvocationId, out ScriptInvocationContext context))

This leads to situations where the if condition in Log() is not met and the logs are not forwarded from the worker, either to the console or to Application Insights.

@fabiocav

[Charles-Gagnon]

@brettsam @fabiocav Has there been additional work on this? We still see this occasionally - lately with the Java worker.

[brettsam]

@Charles-Gagnon -- yes, we know what the underlying issue is. I'm working on a fix that will likely roll out very slowly (not on by default, although I'll ping here when something is available to test).

It's in the hot path for function invocations, so we want to make sure we're taking everything into consideration as we improve this.

[oshihirii]

Just wondering if there is any update on this, it is hard to troubleshoot errors and 204 No Content responses from Microsoft Graph API when I cannot rely on context.log(some_value) to print out relevant values in the correct order or at all - sometimes, for example, the function shows as 'executed' in the terminal before the logs are printed. So it makes me question if there is something wrong with async responses I am awaiting on before the function completes etc.

[samir080890]

We have a Function App triggered by Service Bus messages and developed in C#. Despite applying the following settings in the host.json file, we are still encountering issues with missing log entries in Azure Application Insights, especially during high message volumes in the Service Bus.

{ "version": "2.0", "logging": { "applicationInsights": { "samplingSettings": { "isEnabled": false }, "enableLiveMetricsFilters": true } } }

To address this concern, we have opened a support ticket (#2311140050002741). Any updates or insights on resolving this issue would be greatly appreciated.

Thank you.

[brettsam]

I apologize for how slow this PR has gone -- but it's a pretty critical change in a very hot path. Coupled with slow releases and hotfixes over the last couple of months, we've been waiting for some other features to stabilize to prevent any bigger issues. The plan is to get this into our first release in the new year.

For those using dotnet-isolated, I'd highly recommend moving to use our Functions Worker Application Insights package. This shifts logging to go directly to App Insights rather than through the host, removing this issue of ordering completely.

See the readme above and also some other comments I've made for more info there:

• adding AI project azure-functions-dotnet-worker#944 (comment)
• Support structured logging from worker #7452 (comment)

[samir080890]

Hello Team,

Although the mentioned issue has been marked as closed, it appears that the problem with missing log entries in function app persists. Kindly review my comment on this issue, which I posted last December 2023, and provide an update on the status.

Thank you.

[RohitRanjanMS]

Hi @samir080890 , your issue may be unrelated to this. Please try modifying max telemetry per second setting and see if it helps.
The code is merged for this fix but the roll-out takes about 2 weeks' time.

[brettsam]

This change has now been (mostly) rolled out to Windows production environments with version 4.30. However, it is not enabled by default just yet. We will be enabling this across different regions and ensuring there are no regressions over the next couple of weeks.

However, if you are experiencing issues with missing logs from workers (and/or out-of-order logs) and want to try it out faster -- you can add an App Setting of AzureWebJobsFeatureFlags with a value of EnableOrderedInvocationMessages. This will restart your app and it should begin using the newer logic to keep log messages in order.

[keidyz]

@brettsam I'm still getting the same ordering issue albeit with way way less frequency.

Posted a question about the ordering scenario on stack overflow from way back then https://stackoverflow.com/questions/75716633/azure-function-context-log-not-logging-properly-not-synchronous along with a repository where you can easily test the ordering issue.