search

microsoft / BotFramework-Composer

Dialog creation and management for Microsoft Bot Framework Applications
https://docs.microsoft.com/en-us/composer/
MIT License
860 stars 366 forks source link

Cannot open PVA in Composer #4851

Closed stephanbisser closed 3 years ago

stephanbisser commented 3 years ago

With the latest release of Composer (I'm running v 1.2.1) it should be possible to open a PVA in Composer via the PVA web portal. But in my case Composer shows to "Connecting ..." splash screen and asks for credentials but doesn't do anything else so the PVA bot is not opened successfully... Any ideas what's missing?

Here's a video showing what's going on:

pva_composer_error_demo

Version

1.2.1

Browser

OS

cwhitten commented 3 years ago

@stephanbisser can you open Composer from a terminal, and before doing so set an environment variable "DEBUG=composer*" in your shell? Once this is done and Composer is open, trigger the import flow and you'll see additional logging that we can look at to see what is going wrong. cc @tonyanziano

stephanbisser commented 3 years ago

This is my output @cwhitten :

(electron) The default value of app.allowRendererProcessReuse is deprecated, it is currently "false". It will change to be "true" in Electron 9. For more information please check https://github.com/electron/electron/issues/18397 Wed, 18 Nov 2020 10:04:37 GMT express-session deprecated undefined resave option; provide resave option at ....\AppData\Local\Programs\Bot Framework Composer\resources\app.asar\node_modules\@bfc\server\build\server.js:46:17 Wed, 18 Nov 2020 10:04:37 GMT express-session deprecated undefined saveUninitialized option; provide saveUninitialized option at ....\AppData\Local\Programs\Bot Framework Composer\resources\app.asar\node_modules\@bfc\server\build\server.js:46:17 Warning: connect.session() MemoryStore is not designed for a production environment, as it will leak memory, and will not scale past a single process. Translation for "VA Core" in "en" is missing Translation for "The core of your new VA - ready to run, just add skills!" in "en" is missing

Composer now running at:

http://localhost:5000

GET / 200 13.633 ms - 898 Checking for update GET /api/featureFlags 304 8.713 ms - - GET /api/extensions 304 1.408 ms - - GET /api/assets/locales/en-US.json 200 35.001 ms - - GET /api/storages 304 0.932 ms - - GET /api/assets/projectTemplates 304 1.045 ms - - GET /api/projects/recent 304 8.444 ms - - GET /api/storages/default/blobs?path=C%253A%252FUsers%252Fsbi%252Fsource%252Frepos%252FComposerTestBots 304 18.489 ms - - Update for version 1.2.1 is not available (latest version: 1.2.1, downgrade is disallowed). GET /projects/import?source=pva&payload=%7B%22botId%22%3A%229ab8f269-27ec-4604-8814-8e3addf77808%22%2C%22envId%22%3A%22Default-58c5e340-26ff-4bdc-8147-0b98e7074323%22%2C%22tenantId%22%3A%2258c5e340-26ff-4bdc-8147-0b98e7074323%22%2C%22name%22%3A%22SBI-Dev%22%2C%22baseUrl%22%3A%22https%3A%2F%2Fpowerva.microsoft.com%2Fapi%2Fbotmanagement%2Fv1%22%7D 200 0.955 ms - 898 GET /api/assets/locales/en-US.json 304 0.933 ms - - GET /api/featureFlags 304 1.832 ms - - GET /api/extensions 304 1.037 ms - - GET /api/storages 304 0.935 ms - - GET /api/assets/projectTemplates 304 0.447 ms - - GET /api/projects/recent 304 5.234 ms - - GET /api/storages/default/blobs?path=C%253A%252FUsers%252Fsbi%252Fsource%252Frepos%252FComposerTestBots 304 17.040 ms - - OneAuth Version 0.15.0 (com.microsoft.BotFrameworkComposer) [OneAuth]:[Error]:[tag_965x9]:[bbe683ae-20a5-439f-9097-f5ce3061aac2]:MakeErrorWithParameters (Code:2400, Source:2) The operation attempted is invalid. Recieved an error from AAD. Code: 'invalid_client' description: '(pii)' correlation id: 'bbe683ae-20a5-439f-9097-f5ce3061aac2' [OneAuth]:[Warning]:[tag_97bcd]:[bbe683ae-20a5-439f-9097-f5ce3061aac2]:operator () Not able to acquire token for Graph resources [OneAuth]:[Error]:[tag_965x9]:[51e89d63-c354-43a1-97f5-412373dfd8bf]:MakeErrorWithParameters (Code:2400, Source:2) The operation attempted is invalid. Recieved an error from AAD. Code: 'invalid_client' description: '(pii)' correlation id: '51e89d63-c354-43a1-97f5-412373dfd8bf' POST /api/import/pva/authenticate?payload=%7B%22botId%22%3A%229ab8f269-27ec-4604-8814-8e3addf77808%22%2C%22envId%22%3A%22Default-58c5e340-26ff-4bdc-8147-0b98e7074323%22%2C%22tenantId%22%3A%2258c5e340-26ff-4bdc-8147-0b98e7074323%22%2C%22name%22%3A%22SBI-Dev%22%2C%22baseUrl%22%3A%22https%3A%2F%2Fpowerva.microsoft.com%2Fapi%2Fbotmanagement%2Fv1%22%7D 500 11420.763 ms - 2

tonyanziano commented 3 years ago

Hey @stephanbisser ,

Thanks for the log output.

Can I please have you try again to capture the output from the terminal, but this time, before starting Composer please run the command set DEBUG=composer* in the same terminal window that you will use to start Composer.

You will be able to tell if the DEBUG variable is set correctly by looking at the output in the terminal. You should see a lot of messages starting with the prefix: composer: like this:

2020-11-18T21:50:09.656Z composer:electron App ready
2020-11-18T21:50:09.656Z composer:electron Loading latest known locale
2020-11-18T21:50:09.659Z composer:electron:electron-window Raw screen dimensions: 1040 x 1920
2020-11-18T21:50:09.659Z composer:electron:electron-window Electron window dimensions: 936 x 1248
2020-11-18T21:50:09.695Z composer:electron:electron-window Rendered Electron window dimensions:  [ 1248, 936 ]
2020-11-18T21:50:10.378Z composer:electron Creating app data directory...
2020-11-18T21:50:10.378Z composer:electron creating composer app data path at:  C:\Users\tonya\AppData\Roaming\BotFrameworkComposer
2020-11-18T21:50:10.378Z composer:electron creating local bot runtime publish path:  C:\Users\tonya\AppData\Roaming\BotFrameworkComposer\hostedBots
2020-11-18T21:50:10.400Z composer:electron Created app data directory.
2020-11-18T21:50:10.400Z composer:electron Starting server...

If you still can't see the extra log messages then we can maybe connect over a quick call and get it sorted out.

One other thing noticed is that the login window does not ask you to perform multi-factor authentication, which seems odd.

Once we get the more detailed log messages then we should have a better understanding of what's happening.

stephanbisser commented 3 years ago

There you go:

Composer now running at:

http://localhost:5000

2020-11-19T07:09:21.053Z composer:electron Server started at port: 5000
2020-11-19T07:09:21.054Z composer:electron Rendering application...
GET / 200 10.784 ms - 898
2020-11-19T07:09:22.924Z composer:electron Initializing app updater...
2020-11-19T07:09:23.004Z composer:electron Initialized
2020-11-19T07:09:23.005Z composer:electron:app-updater Updates set to be retrieved from stable repo.
2020-11-19T07:09:23.015Z composer:electron:app-updater Updating from stable to stable. Not allowing downgrade.
Checking for update
2020-11-19T07:09:23.016Z composer:electron:app-updater Checking for updates...
2020-11-19T07:09:23.017Z composer:electron App updater initialized.
GET /api/assets/locales/en-US.json 200 18.488 ms - -
GET /api/featureFlags 304 9.237 ms - -
GET /api/extensions 304 1.970 ms - -
Update for version 1.2.1 is not available (latest version: 1.2.1, downgrade is disallowed).
2020-11-19T07:09:27.335Z composer:electron:app-updater Update not available: {
  version: '1.2.1',
  releaseDate: '2020-11-16T18:19:21.722Z',
  githubArtifactName: 'BotFramework-Composer-1.2.1-windows-setup.exe',
  path: 'BotFramework-Composer-1.2.1-windows-setup.exe',
  sha512: '0eLRWIDrKgS+B0vQLTqXOnmQ4m6l6NVlHf+RZFN0SCLXNwUSuUT4OKZ2BtvBP57LnBbM1OiX3lI+K6yMLFsTsA==',
  releaseName: '1.2.1',
  releaseNotes: '<p>This is a <strong>STABLE</strong> release of Composer.</p>\n' +
    '<p><a href="https://github.com/microsoft/BotFramework-Composer/blob/main/releases/1.2.1.md">https://github.com/microsoft/BotFramework-Composer/blob/main/releases/1.2.1.md</a></p>'
}
2020-11-19T07:09:27.336Z composer:electron:app-updater Resetting to idle...
GET /api/storages 304 1.443 ms - -
GET /api/assets/projectTemplates 304 0.976 ms - -
GET /api/projects/recent 304 16.945 ms - -
GET /api/storages/default/blobs?path=C%253A%252FUsers%252Fsbi%252Fsource%252Frepos%252FComposerTestBots 304 22.675 ms - -
2020-11-19T07:09:28.318Z composer:electron Rendered application.
2020-11-19T07:09:28.869Z composer:electron [Windows] Main window is now showing. Processing deep link if any.
2020-11-19T07:09:46.762Z composer:electron [Windows] Loading deeplink: projects/import?source=pva&payload=%7B%22botId%22%3A%229ab8f269-27ec-4604-8814-8e3addf77808%22%2C%22envId%22%3A%22Default-58c5e340-26ff-4bdc-8147-0b98e7074323%22%2C%22tenantId%22%3A%2258c5e340-26ff-4bdc-8147-0b98e7074323%22%2C%22name%22%3A%22SBI-Dev%22%2C%22baseUrl%22%3A%22https%3A%2F%2Fpowerva.microsoft.com%2Fapi%2Fbotmanagement%2Fv1%22%7D
GET /projects/import?source=pva&payload=%7B%22botId%22%3A%229ab8f269-27ec-4604-8814-8e3addf77808%22%2C%22envId%22%3A%22Default-58c5e340-26ff-4bdc-8147-0b98e7074323%22%2C%22tenantId%22%3A%2258c5e340-26ff-4bdc-8147-0b98e7074323%22%2C%22name%22%3A%22SBI-Dev%22%2C%22baseUrl%22%3A%22https%3A%2F%2Fpowerva.microsoft.com%2Fapi%2Fbotmanagement%2Fv1%22%7D 200 1.267 ms - 898
GET /api/assets/locales/en-US.json 304 1.736 ms - -
GET /api/extensions 304 1.614 ms - -
GET /api/featureFlags 304 6.644 ms - -
GET /api/storages 304 0.974 ms - -
GET /api/assets/projectTemplates 304 0.640 ms - -
GET /api/projects/recent 304 4.736 ms - -
GET /api/storages/default/blobs?path=C%253A%252FUsers%252Fsbi%252Fsource%252Frepos%252FComposerTestBots 304 17.772 ms - -
2020-11-19T07:09:50.935Z composer:pva-provider Using PROD auth credentials.
2020-11-19T07:09:50.936Z composer:electron-auth-provider Getting access token.
2020-11-19T07:09:50.936Z composer:electron-auth-provider Did not find cached token. Getting fresh token.
2020-11-19T07:09:50.937Z composer:electron:one-auth PII logging enabled: false
2020-11-19T07:09:50.938Z composer:electron:one-auth Attempting to load oneauth module from C:\Users\sbi\AppData\Local\Programs\Bot Framework Composer\resources\app.asar.unpacked\oneauth.
2020-11-19T07:09:51.060Z composer:electron:one-auth Initializing...
OneAuth Version 0.15.0 (com.microsoft.BotFrameworkComposer)
2020-11-19T07:09:51.074Z composer:electron:one-auth Service initialized.
2020-11-19T07:09:51.074Z composer:electron:one-auth Getting access token...
2020-11-19T07:09:51.074Z composer:electron:one-auth No signed in account found. Signing user in before getting access token.
2020-11-19T07:09:51.075Z composer:electron:one-auth Signing in...
2020-11-19T07:09:51.475Z composer:electron:one-auth 4 [MSAL] INFO    AuthenticatorFactoryInternalImpl.cpp:87: Starting up MSAL
2020-11-19T07:09:51.476Z composer:electron:one-auth 4 [MSAL] INFO    AuthenticatorFactoryInternalImpl.cpp:164: Created a new public client application with ID ''
2020-11-19T07:09:51.476Z composer:electron:one-auth 4 OneAuth Version 0.15.0 (com.microsoft.BotFrameworkComposer)
2020-11-19T07:10:02.651Z composer:electron:one-auth 4 [MSAL] INFO    AuthenticatorFactoryInternalImpl.cpp:217: Embedded browser factory has been set successfully
2020-11-19T07:10:04.848Z composer:electron:one-auth 4 [MSAL] INFO    HttpManagerImpl.cpp:71: Completed HTTP request to '(pii)' with status code 200, downloaded 5806 characters and 14 headers.
2020-11-19T07:10:04.848Z composer:electron:one-auth 4 [MSAL] INFO    AADTokenResponse.cpp:146: Successfully parsed AAD response and got a token!
2020-11-19T07:10:04.973Z composer:electron:one-auth 3 [MSAL] WARNING StorageTokenResponse.cpp:38: No credentials found in the cache
2020-11-19T07:10:04.973Z composer:electron:one-auth 3 [MSAL] WARNING CacheManager.cpp:156: No id token found in the cache
2020-11-19T07:10:04.973Z composer:electron:one-auth 3 [MSAL] WARNING CacheManager.cpp:161: No access token found in the cache
2020-11-19T07:10:05.022Z composer:electron:one-auth 4 [MSAL] INFO    HttpManagerImpl.cpp:71: Completed HTTP request to '(pii)' with status code 200, downloaded 368 characters and 14 headers.
2020-11-19T07:10:05.221Z composer:electron:one-auth 4 [MSAL] INFO    HttpManagerImpl.cpp:71: Completed HTTP request to '(pii)' with status code 200, downloaded 34395 characters and 4 headers.
2020-11-19T07:10:05.260Z composer:electron:one-auth 4 [MSAL] INFO    HttpManagerImpl.cpp:71: Completed HTTP request to '(pii)' with status code 200, downloaded 6318 characters and 5 headers.
2020-11-19T07:10:05.518Z composer:electron:one-auth 4 [MSAL] INFO    HttpManagerImpl.cpp:71: Completed HTTP request to '(pii)' with status code 401, downloaded 530 characters and 14 headers.
2020-11-19T07:10:05.518Z composer:electron:one-auth 3 [MSAL] WARNING TelemetryImpl.cpp:66: Attempted to add a field to telemetry with an empty value. Ignoring this field.
2020-11-19T07:10:05.518Z composer:electron:one-auth 2 [MSAL] ERROR   ErrorInternalImpl.cpp:85: Created an error: tag_965x9, StatusInternal::ApiContractViolation, InternalEvent::None, Error Code 0, Context 'Recieved an error from AAD. Code: 'invalid_client' description: '(pii)' correlation id: '6ebdd643-7927-4ccd-8ffd-8da50d8159c1''
[OneAuth]:[Error]:[tag_965x9]:[6ebdd643-7927-4ccd-8ffd-8da50d8159c1]:MakeErrorWithParameters (Code:2400, Source:2) The operation attempted is invalid.
Recieved an error from AAD. Code: 'invalid_client' description: '(pii)' correlation id: '6ebdd643-7927-4ccd-8ffd-8da50d8159c1'
[OneAuth]:[Warning]:[tag_97bcd]:[6ebdd643-7927-4ccd-8ffd-8da50d8159c1]:operator () Not able to acquire token for Graph resources
2020-11-19T07:10:05.520Z composer:electron:one-auth 2 [OneAuth]:[Error]:[tag_965x9]:[6ebdd643-7927-4ccd-8ffd-8da50d8159c1]:MakeErrorWithParameters (Code:2400, Source:2) The operation attempted is invalid.
Recieved an error from AAD. Code: 'invalid_client' description: '(pii)' correlation id: '6ebdd643-7927-4ccd-8ffd-8da50d8159c1'
2020-11-19T07:10:05.520Z composer:electron:one-auth 3 [OneAuth]:[Warning]:[tag_97bcd]:[6ebdd643-7927-4ccd-8ffd-8da50d8159c1]:operator () Not able to acquire token for Graph resources
2020-11-19T07:10:05.521Z composer:electron:one-auth Signed in successfully. Got account: {
  id: '6bf20ff3-45cc-4984-bdac-2b7c4f21b79f',
  accountType: 2,
  authority: 'https://login.microsoftonline.com/common',
  sovereignty: 'Global',
  environment: 'login.microsoftonline.com',
  loginName: 'stephan.bisser@solvion.net',
  displayName: 'Stephan Bisser',
  providerId: '6bf20ff3-45cc-4984-bdac-2b7c4f21b79f',
  realm: 'common',
  givenName: '',
  middleName: '',
  familyName: '',
  email: '',
  phoneNumber: '',
  sid: '',
  accountHints: [ 'stephan.bisser@solvion.net' ],
  hosts: []
}
2020-11-19T07:10:05.581Z composer:electron:one-auth 3 [MSAL] WARNING StorageTokenResponse.cpp:38: No credentials found in the cache
2020-11-19T07:10:05.581Z composer:electron:one-auth 3 [MSAL] WARNING CacheManager.cpp:156: No id token found in the cache
2020-11-19T07:10:05.582Z composer:electron:one-auth 3 [MSAL] WARNING CacheManager.cpp:161: No access token found in the cache
2020-11-19T07:10:05.597Z composer:electron:one-auth 4 [MSAL] INFO    HttpManagerImpl.cpp:71: Completed HTTP request to '(pii)' with status code 200, downloaded 368 characters and 14 headers.
2020-11-19T07:10:05.599Z composer:electron:one-auth 4 [MSAL] INFO    HttpManagerImpl.cpp:71: Completed HTTP request to '(pii)' with status code 200, downloaded 34395 characters and 2 headers.
2020-11-19T07:10:05.625Z composer:electron:one-auth 4 [MSAL] INFO    HttpManagerImpl.cpp:71: Completed HTTP request to '(pii)' with status code 200, downloaded 6318 characters and 5 headers.
[OneAuth]:[Error]:[tag_965x9]:[ac0773b8-c0ec-460d-825e-869eddfd78bf]:MakeErrorWithParameters (Code:2400, Source:2) The operation attempted is invalid.
Recieved an error from AAD. Code: 'invalid_client' description: '(pii)' correlation id: 'ac0773b8-c0ec-460d-825e-869eddfd78bf'2020-11-19T07:10:05.914Z composer:electron:one-auth 4 [MSAL] INFO    HttpManagerImpl.cpp:71: Completed HTTP request to '(pii)' with status code 401, downloaded 530 characters and 14 headers.

2020-11-19T07:10:05.915Z composer:electron:one-auth 3 [MSAL] WARNING TelemetryImpl.cpp:66: Attempted to add a field to telemetry with an empty value. Ignoring this field.
2020-11-19T07:10:05.915Z composer:electron:one-auth 2 [MSAL] ERROR   ErrorInternalImpl.cpp:85: Created an error: tag_965x9, StatusInternal::ApiContractViolation, InternalEvent::None, Error Code 0, Context 'Recieved an error from AAD. Code: 'invalid_client' description: '(pii)' correlation id: 'ac0773b8-c0ec-460d-825e-869eddfd78bf''
2020-11-19T07:10:05.916Z composer:electron:one-auth 2 [OneAuth]:[Error]:[tag_965x9]:[ac0773b8-c0ec-460d-825e-869eddfd78bf]:MakeErrorWithParameters (Code:2400, Source:2) The operation attempted is invalid.
Recieved an error from AAD. Code: 'invalid_client' description: '(pii)' correlation id: 'ac0773b8-c0ec-460d-825e-869eddfd78bf'
2020-11-19T07:10:05.917Z composer:electron:one-auth Error while trying to get an access token: {
  error: {
    toString: 'ApiContractViolation {"Description":"The operation attempted is invalid.","ErrorCode":"2400","Tag":"965x9"}',
    status: 6,
    diagnostics: {
      tag: '965x9',
      errorCode: '2400',
      description: 'The operation attempted is invalid.'
    }
  }
}
2020-11-19T07:10:05.917Z composer:electron-auth-provider Error while trying to get access token: {
  error: {
    toString: 'ApiContractViolation {"Description":"The operation attempted is invalid.","ErrorCode":"2400","Tag":"965x9"}',
    status: 6,
    diagnostics: {
      tag: '965x9',
      errorCode: '2400',
      description: 'The operation attempted is invalid.'
    }
  }
}
2020-11-19T07:10:05.918Z composer Error while trying to get a PVA access token: User cancelled login flow.
POST /api/import/pva/authenticate?payload=%7B%22botId%22%3A%229ab8f269-27ec-4604-8814-8e3addf77808%22%2C%22envId%22%3A%22Default-58c5e340-26ff-4bdc-8147-0b98e7074323%22%2C%22tenantId%22%3A%2258c5e340-26ff-4bdc-8147-0b98e7074323%22%2C%22name%22%3A%22SBI-Dev%22%2C%22baseUrl%22%3A%22https%3A%2F%2Fpowerva.microsoft.com%2Fapi%2Fbotmanagement%2Fv1%22%7D 500 14984.355 ms - 2

What's strange is that it says "User cancelled login flow" which is not the case, as I only get asked for the username and that's it...

tonyanziano commented 3 years ago

Awesome, that's what I was looking for! Thanks.

Don't worry about the "User cancelled login flow," that's error handling on the Composer side that's not fully polished yet.

I'm going to run this by the maintainers of the auth library and see if they can help me debug the error message and I'll update this thread accordingly.

stephanbisser commented 3 years ago

Any updates already @tonyanziano?

tonyanziano commented 3 years ago

Hello @stephanbisser ,

I was on vacation during the week of Thanksgiving, but there is an ongoing thread between me and the maintainers of the authentication library and we are trying to debug the issue.

I'll keep you updated.

tonyanziano commented 3 years ago

Hey @stephanbisser ,

I have been going back and forth with the OneAuth team, and we believe we have found the issue. There was an error in one of our build scripts that was embedding an older version of the authentication library into Composer than what was intended.

We have a fix that resolves this issue and pulls in the updated version which should contain several bug fixes including a fix for the error that you are experiencing.

I'll let you know when we get out an updated release, but it should be out by the end of the week.

stephanbisser commented 3 years ago

@tonyanziano great news thanks! looking forward!

tonyanziano commented 3 years ago

Hey @stephanbisser ,

Please try out the latest nightly version available here and let me know if you are still experiencing the issue.

tonyanziano commented 3 years ago

Going to close as stale for now. Please feel free to let us know if your issue is fixed or reopen if you're still experiencing the issue.