Azure / Azure/azure-functions-host
Log socket connection errors between host and language worker processes
- Dominant language
- C#
- Stars
- 2k
- Forks
- 482
- Avg merge
- 2d 12h
- Merged PRs (30d)
- 38
Description
**Issue**
This is a repair item from an incident where there were socket connection failures on the worker VM causing no messages to reach from the powershell language worker and the functions host. The impact was that from customer's app insights logs and our Kusto logs it looked like the host queued up the function invocation but never received any message back from the language worker process.
**Solution**
To root cause such failures, it would be ideal to log these connectivity issues in the functions logs table. This will help customers identify issues as to why their function invocations are not finishing up.
**Sample failures -**
let ST = datetime(2021-06-03T03:29:00Z);
let ET = datetime(2021-06-03T05:30:00Z);
FunctionsLogs
| where PreciseTimeStamp between (ST..ET)
| where EventPrimaryStampName == "waws-prod-bn1-031" and EventStampName == "waws-prod-bn1-031e" and RoleInstance == "SmallDedicatedWebWorkerRole_IN_64"
| where * contains "a8919b94-6e0f-48a7-b53c-3c2acad31fda"
| where Pid == 8768
| project PreciseTimeStamp, Source, Pid, Summary, Level
<!--
/* Font Definitions */
@font-face
{font-family:"Cambria Math";
panose-1:2 4 5 3 5 4 6 3 2 4;
mso-font-alt:"Calisto MT";
mso-font-charset:0;
mso-generic-font-family:roman;
mso-font-pitch:variable;
mso-font-signature:-536869121 1107305727 33554432 0 415 0;}
@font-face
{font-family:Calibri;
panose-1:2 15 5 2 2 2 4 3 2 4;
mso-font-alt:"Arial Rounded MT Bold";
mso-font-charset:0;
mso-generic-font-family:swiss;
mso-font-pitch:variable;
mso-font-signature:-469750017 -1073732485 9 0 511 0;}
@font-face
{font-family:"Segoe UI";
panose-1:2 11 5 2 4 2 4 2 2 3;
mso-font-alt:"Century Gothic";
mso-font-charset:0;
mso-generic-font-family:swiss;
mso-font-pitch:variable;
mso-font-signature:-469750017 -1073683329 9 0 511 0;}
@font-face
{font-family:Consolas;
panose-1:2 11 6 9 2 2 4 3 2 4;
mso-font-charset:0;
mso-generic-font-family:modern;
mso-font-pitch:fixed;
mso-font-signature:-536869121 64767 1 0 415 0;}
/* Style Definitions */
p.MsoNormal, li.MsoNormal, div.MsoNormal
{mso-style-unhide:no;
mso-style-qformat:yes;
mso-style-parent:"";
margin:0in;
mso-pagination:widow-orphan;
font-size:11.0pt;
font-family:"Calibri",sans-serif;
mso-fareast-font-family:Calibri;
mso-fareast-theme-font:minor-latin;}
.MsoChpDefault
{mso-style-type:export-only;
mso-default-props:yes;
font-size:10.0pt;
mso-ansi-font-size:10.0pt;
mso-bidi-font-size:10.0pt;}
@page WordSection1
{size:8.5in 11.0in;
margin:1.0in 1.0in 1.0in 1.0in;
mso-header-margin:.5in;
mso-footer-margin:.5in;
mso-paper-source:0;}
div.WordSection1
{page:WordSection1;}
-->
| PreciseTimeStamp | Source | Pid | Summary | Level
-- | -- | -- | -- | -- | --
| 2021-06-03 03:30:00.5957876 | Function.sqlDB-Maintenance | 8768 | Executing 'Functions.sqlDB-Maintenance' (Reason='Timer fired at 2021-06-03T03:30:00.4179878+00:00', Id=a8919b94-6e0f-48a7-b53c-3c2acad31fda) | 4
| 2021-06-03 03:30:02.1408328 | Worker.rpcWorkerProcess.powershell.ee7f34b7-e5dc-4d19-bd45-eaf8fda8b788 | 8768 | System Log: { Invocation-Id: a8919b94-6e0f-48a7-b53c-3c2acad31fda; Log-Level: Trace; Log-Message: Profile invocation completed in 1121 ms. } | 5
| 2021-06-03 03:30:02.2630177 | Worker.rpcWorkerProcess.powershell.ee7f34b7-e5dc-4d19-bd45-eaf8fda8b788 | 8768 | System Log: { Invocation-Id: a8919b94-6e0f-48a7-b53c-3c2acad31fda; Log-Level: Trace; Log-Message: Invoking function 'sqlDB-Maintenance' code 1392 ms after receiving request. Invocation performance details: DependenciesAvailable: 3 ms; RunspaceAvailable: 1275 ms; MetadataAndTraceContextReady: 1277 ms; FunctionCodeReady: 1279 ms; InputBindingValuesReady: 1390 ms; InvokingFunctionCode: 1390 ms; } | 5
As it shows here, we only see the log message for queuing up the function invocation id - a8919b94-6e0f-48a7-b53c-3c2acad31fda, but we never see the corresponding log entry for the finished execution. There is no error logged in the functions host which shows the connectivity failures between the host and the language worker process. The only place we could find the error was in the Recommendation Events. We should consider logging such failures to our Kusto and customer app insights to make it easier to detect such issues.
cc @Francisco-Gamino
Contributor guide
Research direction
Start by tracing socket communication between the PowerShell language worker and the Functions host, then identify the existing path for entries in the FunctionsLogs table. Done means socket connection failures are recorded in function logs with enough context for customers to diagnose invocations that do not finish.
Written by the indexing model from the issue text.
Assessment
- Tech stack
- azure, csharp, powershell
- Domain
- backend, observability
- Issue type
- Bug
- Difficulty
- 4/5
- Estimated time
- 3-5 days
- Activity status
- Stale
- Clarity
- Needs clarification
- Newbie friendliness
- 25/100