Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

After update to 4.5.6 Azure NodeJS Function Fails - isPlainObject is not a functionat Object.keys.forEach.key #195

Closed
warrenbuckley opened this issue Sep 15, 2020 · 14 comments
Assignees
Labels
Type: Support Any questions, information, or general needs around the SDK or GitHub APIs
Projects

Comments

@warrenbuckley
Copy link

warrenbuckley commented Sep 15, 2020

Problem

After upgrading to the latest version 4.5.6 a NodeJS serverless Azure Function now complains about
isPlainObject is not a function at Object.keys.forEach.key

If I revert the package.json dependency back to 4.5.4 then it continues to work as it once did.

Error

2020-09-15T11:38:06.357 [Error] Executed 'Functions.IsActiveSponsor' (Failed, Id=aaee2f87-29b6-43d9-8f2f-92c964e370bf, Duration=11ms)Result: FailureException: Worker was unable to load function IsActiveSponsor: 'TypeError: isPlainObject is not a function'
Stack: TypeError: isPlainObject is not a functionat Object.keys.forEach.key (D:\home\site\wwwroot\node_modules\@octokit\endpoint\dist-node\index.js:24:9)
  at Array.forEach (<anonymous>)
  at mergeDeep (D:\home\site\wwwroot\node_modules\@octokit\endpoint\dist-node\index.js:23:24)
  at merge (D:\home\site\wwwroot\node_modules\@octokit\endpoint\dist-node\index.js:52:25)
  at withDefaults (D:\home\site\wwwroot\node_modules\@octokit\endpoint\dist-node\index.js:348:20)
  at Object.<anonymous> (D:\home\site\wwwroot\node_modules\@octokit\endpoint\dist-node\index.js:376:18)
  at Module._compile (internal/modules/cjs/loader.js:778:30)
  at Object.Module._extensions..js (internal/modules/cjs/loader.js:789:10)
  at Module.load (internal/modules/cjs/loader.js:653:32)
  at tryModuleLoad (internal/modules/cjs/loader.js:593:12)

image

@ghost ghost added this to Inbox in JS Sep 15, 2020
@gr2m
Copy link
Contributor

gr2m commented Sep 15, 2020

is-plain-object was recently bumped to v5 via https://github.com/octokit/endpoint.js/releases/tag/v6.0.6, but the code was adjusted accordingly.

Do you have a lock file? Could you provide the output of npm ls | grep octokit (or the yarn equivalent if you use that)?

I'm not able to reproduce the problem with the information you shared. If you could create a minimal test that would be great. runkit.com/ is great for that, see https://runkit.com/gr2m/octokit-rest-js-1808 for an example

@gr2m gr2m added the Type: Support Any questions, information, or general needs around the SDK or GitHub APIs label Sep 15, 2020
@ghost ghost moved this from Inbox to Support in JS Sep 15, 2020
@warrenbuckley
Copy link
Author

@gr2m this works fine locally for me, it is only when this is pushed into Azure itself that it causes this problem, which is obviously tricky to replicate.

With this seeming to be specific to Azure as I can not reproduce this locally, I am not sure a RunKit will help us, but will create one if you want me to. If there any other details or specifics you wish for me to investigate with Azure to help diagnose then please let me know :)

For reference my relatively simple Azure Function code using Octokit/GraphQL is here
https://github.com/warrenbuckley/Is-Github-Sponsor/blob/master/IsActiveSponsor/index.ts
https://github.com/warrenbuckley/Is-Github-Sponsor

Poking around in Azure Portal it mentions it is running 10.19.0 of Node
"WEBSITE_NODE_DEFAULT_VERSION": "10.19.0"

Result of npm ls (Local Machine)

image

Result of npm ls (Azure)

image

package.lock.json

{
  "name": "isgithubsponsor",
  "version": "1.0.0",
  "lockfileVersion": 1,
  "requires": true,
  "dependencies": {
    "@azure/functions": {
      "version": "1.2.2",
      "resolved": "https://registry.npmjs.org/@azure/functions/-/functions-1.2.2.tgz",
      "integrity": "sha512-p/dDHq1sG/iAib+eDY4NxskWHoHW1WFzD85s0SfWxc2wVjJbxB0xz/zBF4s7ymjVgTu+0ceipeBk+tmpnt98oA==",
      "dev": true
    },
    "@octokit/endpoint": {
      "version": "6.0.6",
      "resolved": "https://registry.npmjs.org/@octokit/endpoint/-/endpoint-6.0.6.tgz",
      "integrity": "sha512-7Cc8olaCoL/mtquB7j/HTbPM+sY6Ebr4k2X2y4JoXpVKQ7r5xB4iGQE0IoO58wIPsUk4AzoT65AMEpymSbWTgQ==",
      "requires": {
        "@octokit/types": "^5.0.0",
        "is-plain-object": "^5.0.0",
        "universal-user-agent": "^6.0.0"
      }
    },
    "@octokit/graphql": {
      "version": "4.5.6",
      "resolved": "https://registry.npmjs.org/@octokit/graphql/-/graphql-4.5.6.tgz",
      "integrity": "sha512-Rry+unqKTa3svswT2ZAuqenpLrzJd+JTv89LTeVa5UM/5OX8o4KTkPL7/1ABq4f/ZkELb0XEK/2IEoYwykcLXg==",
      "requires": {
        "@octokit/request": "^5.3.0",
        "@octokit/types": "^5.0.0",
        "universal-user-agent": "^6.0.0"
      }
    },
    "@octokit/request": {
      "version": "5.4.9",
      "resolved": "https://registry.npmjs.org/@octokit/request/-/request-5.4.9.tgz",
      "integrity": "sha512-CzwVvRyimIM1h2n9pLVYfTDmX9m+KHSgCpqPsY8F1NdEK8IaWqXhSBXsdjOBFZSpEcxNEeg4p0UO9cQ8EnOCLA==",
      "requires": {
        "@octokit/endpoint": "^6.0.1",
        "@octokit/request-error": "^2.0.0",
        "@octokit/types": "^5.0.0",
        "deprecation": "^2.0.0",
        "is-plain-object": "^5.0.0",
        "node-fetch": "^2.6.1",
        "once": "^1.4.0",
        "universal-user-agent": "^6.0.0"
      }
    },
    "@octokit/request-error": {
      "version": "2.0.2",
      "resolved": "https://registry.npmjs.org/@octokit/request-error/-/request-error-2.0.2.tgz",
      "integrity": "sha512-2BrmnvVSV1MXQvEkrb9zwzP0wXFNbPJij922kYBTLIlIafukrGOb+ABBT2+c6wZiuyWDH1K1zmjGQ0toN/wMWw==",
      "requires": {
        "@octokit/types": "^5.0.1",
        "deprecation": "^2.0.0",
        "once": "^1.4.0"
      }
    },
    "@octokit/types": {
      "version": "5.5.0",
      "resolved": "https://registry.npmjs.org/@octokit/types/-/types-5.5.0.tgz",
      "integrity": "sha512-UZ1pErDue6bZNjYOotCNveTXArOMZQFG6hKJfOnGnulVCMcVVi7YIIuuR4WfBhjo7zgpmzn/BkPDnUXtNx+PcQ==",
      "requires": {
        "@types/node": ">= 8"
      }
    },
    "@types/node": {
      "version": "14.10.1",
      "resolved": "https://registry.npmjs.org/@types/node/-/node-14.10.1.tgz",
      "integrity": "sha512-aYNbO+FZ/3KGeQCEkNhHFRIzBOUgc7QvcVNKXbfnhDkSfwUv91JsQQa10rDgKSTSLkXZ1UIyPe4FJJNVgw1xWQ=="
    },
    "deprecation": {
      "version": "2.3.1",
      "resolved": "https://registry.npmjs.org/deprecation/-/deprecation-2.3.1.tgz",
      "integrity": "sha512-xmHIy4F3scKVwMsQ4WnVaS8bHOx0DmVwRywosKhaILI0ywMDWPtBSku2HNxRvF7jtwDRsoEwYQSfbxj8b7RlJQ=="
    },
    "is-plain-object": {
      "version": "5.0.0",
      "resolved": "https://registry.npmjs.org/is-plain-object/-/is-plain-object-5.0.0.tgz",
      "integrity": "sha512-VRSzKkbMm5jMDoKLbltAkFQ5Qr7VDiTFGXxYFXXowVj387GeGNOCsOH6Msy00SGZ3Fp84b1Naa1psqgcCIEP5Q=="
    },
    "node-fetch": {
      "version": "2.6.1",
      "resolved": "https://registry.npmjs.org/node-fetch/-/node-fetch-2.6.1.tgz",
      "integrity": "sha512-V4aYg89jEoVRxRb2fJdAg8FHvI7cEyYdVAh94HH0UIK8oJxUfkjlDQN9RbMx+bEjP7+ggMiFRprSti032Oipxw=="
    },
    "once": {
      "version": "1.4.0",
      "resolved": "https://registry.npmjs.org/once/-/once-1.4.0.tgz",
      "integrity": "sha1-WDsap3WWHUsROsF9nFC6753Xa9E=",
      "requires": {
        "wrappy": "1"
      }
    },
    "typescript": {
      "version": "4.0.2",
      "resolved": "https://registry.npmjs.org/typescript/-/typescript-4.0.2.tgz",
      "integrity": "sha512-e4ERvRV2wb+rRZ/IQeb3jm2VxBsirQLpQhdxplZ2MEzGvDkkMmPglecnNDfSUBivMjP93vRbngYYDQqQ/78bcQ==",
      "dev": true
    },
    "universal-user-agent": {
      "version": "6.0.0",
      "resolved": "https://registry.npmjs.org/universal-user-agent/-/universal-user-agent-6.0.0.tgz",
      "integrity": "sha512-isyNax3wXoKaulPDZWHQqbmIx1k2tb9fb3GGDBRxCscfYV2Ch7WxPArBsFEG8s/safwXTT7H4QGhaIkTp9447w=="
    },
    "wrappy": {
      "version": "1.0.2",
      "resolved": "https://registry.npmjs.org/wrappy/-/wrappy-1.0.2.tgz",
      "integrity": "sha1-tSQ9jz7BqjXxNkYFvA0QNuMKtp8="
    }
  }
}

@gr2m
Copy link
Contributor

gr2m commented Sep 16, 2020

It all looks correct to me ...

Could you create a much more reduced function and see if it causes the same problem, something like this?

import { Context, HttpRequest } from "@azure/functions"
import { graphql } from "@octokit/graphql";

// Azure Function HTTP Trigger entry point
export default async function (context: Context, req: HttpRequest): Promise<void> {
  const userToken = (req.query.token || (req.body && req.body.token));
  const graphqlWithAuth = graphql.defaults({
    headers: {
      authorization: `token ${userToken}`,
    },
  });
  
  const { data } = await graphqlWithAuth(`{
    viewer {
      login
    }
  }`)
  console.log(data)
  
  context.res = {
    status: 200,
    body: data
  }
  context.done()
}

Can you tell what windows operating system the function is running on? We could try to reproduce it with GitHub Actions running on Windows

@warrenbuckley
Copy link
Author

warrenbuckley commented Sep 17, 2020

Azure Windows OS

Azure = 10.0.14393.0
Local = 10.0.19041

image

Simple example

I have deployed the simple example too and also get the error
https://github-sponsor-check-deploy.azurewebsites.net/GithubIssue?token=PAT_TOKEN_WITH_USER_READ

Git Commit in Repo that Deployed to Azure Functions
warrenbuckley/Is-Github-Sponsor@e689f28

Works locally in VSCode

image

Live Logs from Azure

2020-09-17T20:09:12  Welcome, you are now connected to log-streaming service. The default timeout is 2 hours. Change the timeout with the App Setting SCM_LOGSTREAM_TIMEOUT (in seconds).
2020-09-17T20:09:11.970 [Information] Loading functions metadata
2020-09-17T20:09:12.046 [Information] 2 functions loaded
2020-09-17T20:09:12.247 [Information] Loading functions metadata
2020-09-17T20:09:12.256 [Information] 2 functions loaded
2020-09-17T20:09:12.415 [Information] FUNCTIONS_WORKER_RUNTIME set to node. Skipping WorkerConfig for language:java
2020-09-17T20:09:12.426 [Information] FUNCTIONS_WORKER_RUNTIME set to node. Skipping WorkerConfig for language:powershell
2020-09-17T20:09:12.454 [Information] Initializing Warmup Extension.
2020-09-17T20:09:12.464 [Information] Initializing Host. OperationId: 'ae821678-e829-46a5-8baa-74a15213cae5'.
2020-09-17T20:09:12.464 [Information] Host initialization: ConsecutiveErrors=0, StartupCount=2, OperationId=ae821678-e829-46a5-8baa-74a15213cae5
2020-09-17T20:09:12.486 [Information] ApplicationInsightsLoggerOptions{"SamplingSettings": {"EvaluationInterval": "00:00:15","InitialSamplingPercentage": 100.0,"MaxSamplingPercentage": 100.0,"MaxTelemetryItemsPerSecond": 20.0,"MinSamplingPercentage": 0.1,"MovingAverageRatio": 0.25,"SamplingPercentageDecreaseTimeout": "00:02:00","SamplingPercentageIncreaseTimeout": "00:15:00"},"SamplingExcludedTypes": "Request","SamplingIncludedTypes": null,"SnapshotConfiguration": null,"EnablePerformanceCountersCollection": true,"HttpAutoCollectionOptions": {"EnableHttpTriggerExtendedInfoCollection": true,"EnableW3CDistributedTracing": true,"EnableResponseHeaderInjection": true},"LiveMetricsInitializationDelay": "00:00:15","EnableLiveMetrics": true,"EnableDependencyTracking": true}
2020-09-17T20:09:12.492 [Information] LoggerFilterOptions{"MinLevel": "None","Rules": [{"ProviderName": null,"CategoryName": null,"LogLevel": null,"Filter": "<AddFilter>b__0"},{"ProviderName": "Microsoft.Azure.WebJobs.Script.WebHost.Diagnostics.SystemLoggerProvider","CategoryName": null,"LogLevel": "None","Filter": null},{"ProviderName": "Microsoft.Azure.WebJobs.Script.WebHost.Diagnostics.SystemLoggerProvider","CategoryName": null,"LogLevel": null,"Filter": "<AddFilter>b__0"},{"ProviderName": "Microsoft.Azure.WebJobs.Logging.ApplicationInsights.ApplicationInsightsLoggerProvider","CategoryName": null,"LogLevel": "Trace","Filter": null}]}
2020-09-17T20:09:12.492 [Information] LoggerFilterOptions{"MinLevel": "None","Rules": [{"ProviderName": null,"CategoryName": null,"LogLevel": null,"Filter": "<AddFilter>b__0"},{"ProviderName": "Microsoft.Azure.WebJobs.Script.WebHost.Diagnostics.SystemLoggerProvider","CategoryName": null,"LogLevel": "None","Filter": null},{"ProviderName": "Microsoft.Azure.WebJobs.Script.WebHost.Diagnostics.SystemLoggerProvider","CategoryName": null,"LogLevel": null,"Filter": "<AddFilter>b__0"},{"ProviderName": "Microsoft.Azure.WebJobs.Logging.ApplicationInsights.ApplicationInsightsLoggerProvider","CategoryName": null,"LogLevel": "Trace","Filter": null}]}
2020-09-17T20:09:12.492 [Information] FunctionResultAggregatorOptions{"BatchSize": 1000,"FlushTimeout": "00:00:30","IsEnabled": true}
2020-09-17T20:09:12.492 [Information] SingletonOptions{"LockPeriod": "00:00:15","ListenerLockPeriod": "00:00:15","LockAcquisitionTimeout": "10675199.02:48:05.4775807","LockAcquisitionPollingInterval": "00:00:05","ListenerLockRecoveryPollingInterval": "00:01:00"}
2020-09-17T20:09:12.493 [Information] HttpOptions{"DynamicThrottlesEnabled": true,"MaxConcurrentRequests": 100,"MaxOutstandingRequests": 200,"RoutePrefix": ""}
2020-09-17T20:09:12.493 [Information] Starting JobHost
2020-09-17T20:09:12.493 [Information] Starting Host (HostId=github-sponsor-check-deploy, InstanceId=cb57cb4f-cdd7-4bd8-8445-87ffb0624771, Version=3.0.14413.0, ProcessId=6956, AppDomainId=1, InDebugMode=True, InDiagnosticMode=False, FunctionsExtensionVersion=~3)
2020-09-17T20:09:12.553 [Information] Loading functions metadata
2020-09-17T20:09:12.555 [Information] FUNCTIONS_WORKER_RUNTIME set to node. Skipping WorkerConfig for language:java
2020-09-17T20:09:12.562 [Information] FUNCTIONS_WORKER_RUNTIME set to node. Skipping WorkerConfig for language:powershell
2020-09-17T20:09:12.575 [Information] Loading proxies metadata
2020-09-17T20:09:12.575 [Information] Initializing Azure Function proxies
2020-09-17T20:09:12.771 [Information] 0 proxies loaded
2020-09-17T20:09:12.771 [Information] 2 functions loaded
2020-09-17T20:09:12.927 [Information] Generating 2 job function(s)
2020-09-17T20:09:12.947 [Information] Found the following functions:Host.Functions.GithubIssueHost.Functions.IsActiveSponsor
2020-09-17T20:09:12.947 [Information] Initializing function HTTP routesMapped function route '/GithubIssue' [get,post] to 'GithubIssue'Mapped function route '/IsActiveSponsor' [get,post] to 'IsActiveSponsor'
2020-09-17T20:09:12.948 [Information] Host initialized (454ms)
2020-09-17T20:09:12.948 [Information] Host started (455ms)
2020-09-17T20:09:12.948 [Information] Job host started
2020-09-17T20:09:13.204 [Information] Executing 'Functions.GithubIssue' (Reason='This function was programmatically called via the host APIs.', Id=178f40e0-f0b2-4cb6-8743-5a48b20e435c)
2020-09-17T20:09:13.857 [Information] Stopping JobHost
2020-09-17T20:09:13.868 [Information] Job host stopped
2020-09-17T20:09:14.261 [Information] Worker process started and initialized.
**2020-09-17T20:09:15.105 [Error] Executed 'Functions.GithubIssue' (Failed, Id=178f40e0-f0b2-4cb6-8743-5a48b20e435c, Duration=1990ms)Result: FailureException: Worker was unable to load function GithubIssue: 'TypeError: isPlainObject is not a function'Stack: TypeError: isPlainObject is not a functionat Object.keys.forEach.key (D:\home\site\wwwroot\node_modules\@octokit\endpoint\dist-node\index.js:24:9)at Array.forEach (<anonymous>)at mergeDeep (D:\home\site\wwwroot\node_modules\@octokit\endpoint\dist-node\index.js:23:24)at merge (D:\home\site\wwwroot\node_modules\@octokit\endpoint\dist-node\index.js:52:25)at withDefaults (D:\home\site\wwwroot\node_modules\@octokit\endpoint\dist-node\index.js:348:20)at Object.<anonymous> (D:\home\site\wwwroot\node_modules\@octokit\endpoint\dist-node\index.js:376:18)at Module._compile (internal/modules/cjs/loader.js:778:30)at Object.Module._extensions..js (internal/modules/cjs/loader.js:789:10)at Module.load (internal/modules/cjs/loader.js:653:32)at tryModuleLoad (internal/modules/cjs/loader.js:593:12)**
2020-09-17T20:09:17.967 [Information] Host lock lease acquired by instance ID '91b8ff87fedc290e94325d825446a804'.

@warrenbuckley
Copy link
Author

warrenbuckley commented Sep 17, 2020

I haven't had time yet, but come across this repo from MS/Azure Functions that may give some insight how this runs on Azure with the slightly vague error we have
https://github.com/Azure/azure-functions-nodejs-worker

Maybe someone from that team/repo could give some insights?

@mhoeger @pragnagopa @yojagad are any of you or anyone you know on your team who could give advice into debugging this problem and understanding why this would work locally but as soon as deployed to an Azure Function it no longer works.

gr2m added a commit that referenced this issue Sep 18, 2020
gr2m added a commit that referenced this issue Sep 18, 2020
gr2m added a commit that referenced this issue Sep 18, 2020
gr2m added a commit that referenced this issue Sep 18, 2020
gr2m added a commit that referenced this issue Sep 18, 2020
gr2m added a commit that referenced this issue Sep 18, 2020
gr2m added a commit that referenced this issue Sep 18, 2020
gr2m added a commit that referenced this issue Sep 18, 2020
@gr2m
Copy link
Contributor

gr2m commented Sep 18, 2020

I've tried to reproduce the problem using the available windows version on GItHub actions, but to no avail:

My test case is here:

const { graphql } = require("./pkg");
run()
async function run () {
console.log('Sending GraphQL request')
try {
const userToken = process.env.GITHUB_TOKEN
const graphqlWithAuth = graphql.defaults({
headers: {
authorization: `token ${userToken}`,
},
});
const result = await graphqlWithAuth(`{
viewer {
login
}
}`)
console.log(result);
} catch(error) {
console.error(error)
}
}

run from this workflow file:

name: Test
"on":
push:
branches:
- 195/import-error-on-windows
jobs:
test:
runs-on: windows-2019
steps:
- uses: actions/checkout@v2
- uses: actions/setup-node@v1
with:
node-version: 10.19.0
- run: npm ci
- run: npm run build
- run: node reproduce-195.js
env:
GITHUB_TOKEN: ${{ secrets.GITHUB_TOKEN }}

@warrenbuckley
Copy link
Author

Thanks for the update. Interesting it’s all fine on a GitHub Action. I suspect there is something specific happening when run as an Azure Function and is environment specific.

If you want me to try anything else let me know please.

@jnwng
Copy link

jnwng commented Sep 19, 2020

having the same issue here when deploying this code to AWS Lambda, although i think its probably an artifact of the bundling process, not the actual environment itself. while i haven't been able to dive deeper into exactly why is-plain-object is making a big fuss here, it is clear that it is linked to is-plain-object@5.0.0. i ended up pinning @octokit/request@5.4.7 and @octokit/endpoint@6.0.5 to make sure not to introduce is-plain-object@5.0 (those are the two versions right before the automated dependabot bump of is-plain-object)

if you're using yarn, setting the resolutions property in package.json like so:

{
   ...
   "resolutions": {
     "@octokit/request": "5.4.7",
     "@octokit/endpoint": "6.0.5"
   }
}

at least got my code working in Lambda with @octokit/graphql@4.5.6

@warrenbuckley
Copy link
Author

Interesting it also happens in an AWS environment and is not 100% specific to Azure Functions. @jnwng does AWS give you more logs or insight to help @gr2m diagnose this issue?

@gr2m
Copy link
Contributor

gr2m commented Sep 20, 2020

Do you use any kind of bundling with webpack or similar?

@gr2m gr2m self-assigned this Sep 21, 2020
@ghost ghost moved this from Support to In progress in JS Sep 21, 2020
@gr2m
Copy link
Contributor

gr2m commented Sep 21, 2020

@jnwng I tried to reproduce the problem on AWS using the aws CLI and following Lambda's deployment instructions: https://docs.aws.amazon.com/lambda/latest/dg/nodejs-package.html, but no luck.

Could you share more details please? I really appreciate both your help to identify the cause of the problem

@warrenbuckley
Copy link
Author

Currently waiting to hear back from MS/Azure team in the above ticket ⬆️
Will keep you posted when I have anything to report back

@warrenbuckley
Copy link
Author

I may close this issue as it currently can not be reproduced in a new Azure Function
Azure/azure-functions-nodejs-worker#335 (comment)

If I ever encounter this problem again or if anyone else does I suggest we re-open this to try & investigate further

JS automation moved this from In progress to Done Oct 1, 2020
@gr2m
Copy link
Contributor

gr2m commented Oct 1, 2020

Thank you Warren for staying on top of it 👍🏼

cyamonide added a commit to gagoar/use-herald-action that referenced this issue Oct 16, 2020
<!--- write down the issue related to this  PR-->

## Description

<!--- Describe your changes in detail -->

This PR attempts to resolve the `is-plain-object` dependency issue by following this comment: octokit/graphql.js#195 (comment)


## Checklist:

<!--- Go over all the following points, and put an `x` in all the boxes that apply. -->
<!--- If you're unsure about any of these, don't hesitate to ask. We're here to help! -->

- [x] My code follows the code style of this project.
- [ ] My change requires a change to the documentation.
- [ ] I have updated the documentation accordingly.
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Type: Support Any questions, information, or general needs around the SDK or GitHub APIs
Projects
No open projects
JS
  
Done
Development

No branches or pull requests

3 participants