Azure / Azure/azure-functions-host

Log socket connection errors between host and language worker processes

Open
#7,633 1 comment 0 reactions 0 assignees View on GitHub
design
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

Open the contributing 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

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.