search

microsoft / botbuilder-tools

Welcome to the Bot Framework Tools repository, which is the home for a set of tools for developers building bots with the Microsoft Bot Framework
https://github.com/Microsoft/botframework
MIT License
444 stars 262 forks source link

az bot facebook show error when "--with-secrets true" option is turned on #1317

Closed eyunzhang closed 5 years ago

eyunzhang commented 5 years ago

I have a facebook channel, and i'm using az bot facebook to manage it. It was working fine until a few days ago with below error: az bot facebook show --subscription xxx --resource-group xx--name xxx --with-secrets true Error occurred in sending request. Please file an issue on https://github.com/Microsoft/botbuilder-tools/issues

If I remove the "--with-secrets true", the command can successfully return right data. Is there any recent change the breaks the command?

dmvtech commented 5 years ago

Hmm, I thought I was able to reproduce it (also with other channels msteams, slack, kik, telegram), but it seems that it is failing even if I remove --with-secrets true

My az cli is 2.0.72

Can you let us know what version of az cli you are using by running az -v?

dmvtech commented 5 years ago

@eyunzhang

Also, did you upgrade az cli recently?

dmvtech commented 5 years ago

Note: Confirmed that functionality is working in 2.0.70

dmvtech commented 5 years ago

Confirmed repro on version 2.0.74

failure: --with-secrets true success: --with-secrets false

eyunzhang commented 5 years ago

Thanks for looking into the issue. Here is the output of my az -v. And I didn't do any update, it's whatever version I installed several weeks ago. It was working fine until sometime recently (around later of last week).

azure-cli 2.0.73 *

command-modules-nspkg 2.0.3 core 2.0.73 * nspkg 3.0.4 telemetry 1.0.3

dmvtech commented 5 years ago

thanks @eyunzhang

Can you try running it with the --debug flag and then sharing the output here?

az bot facebook show --subscription xxx --resource-group xx--name xxx --with-secrets true --debug

eyunzhang commented 5 years ago

Here is the output. Please note that I have replaced my real subscription, resource-group and name with place holders.

Command arguments: ['bot', 'facebook', 'show', '--subscription', 'subscriptionId', '--resource-group', 'resource-group', '--name', 'resource-name', '--with-secrets', 'true', '--debug'] Event: Cli.PreExecute [] Event: CommandParser.OnGlobalArgumentsCreate [<function CLILogging.on_global_arguments at 0x0367F978>, <function OutputProducer.on_global_arguments at 0x036CB660>, <function CLIQuery.on_global_arguments at 0x03727738>] Event: CommandInvoker.OnPreCommandTableCreate [] Installed command modules ['acr', 'acs', 'advisor', 'ams', 'apim', 'appconfig', 'appservice', 'backup', 'batch', 'batchai', 'billing', 'botservice', 'cdn', 'cloud', 'cognitiveservices', 'configure', 'consumption', 'container', 'cosmosdb', 'deploymentmanager', 'dla', 'dls', 'dms', 'eventgrid', 'eventhubs', 'extension', 'feedback', 'find', 'hdinsight', 'interactive', 'iot', 'iotcentral', 'keyvault', 'kusto', 'lab', 'managedservices', 'maps', 'monitor', 'natgateway', 'netappfiles', 'network', 'policyinsights', 'privatedns', 'profile', 'rdbms', 'redis', 'relay', 'reservations', 'resource', 'role', 'search', 'security', 'servicebus', 'servicefabric', 'signalr', 'sql', 'sqlvm', 'storage', 'vm'] Loaded module 'acr' in 0.008 seconds. Loaded module 'acs' in 0.016 seconds. Loaded module 'advisor' in 0.005 seconds. Event: CommandLoader.OnLoadCommandTable [] Loaded module 'ams' in 0.010 seconds. Loaded module 'apim' in 0.004 seconds. Loaded module 'appconfig' in 0.006 seconds. Loaded module 'appservice' in 0.019 seconds. Loaded module 'backup' in 0.009 seconds. Event: CommandLoader.OnLoadCommandTable [] Loaded module 'batch' in 0.023 seconds. Loaded module 'batchai' in 0.007 seconds. Loaded module 'billing' in 0.010 seconds. Loaded module 'botservice' in 0.007 seconds. Event: CommandLoader.OnLoadCommandTable [] Loaded module 'cdn' in 0.011 seconds. Loaded module 'cloud' in 0.005 seconds. Loaded module 'cognitiveservices' in 0.005 seconds. Loaded module 'configure' in 0.005 seconds. Loaded module 'consumption' in 0.008 seconds. Loaded module 'container' in 0.007 seconds. Loaded module 'cosmosdb' in 0.016 seconds. Loaded module 'deploymentmanager' in 0.008 seconds. Loaded module 'dla' in 0.010 seconds. Loaded module 'dls' in 0.008 seconds. Loaded module 'dms' in 0.006 seconds. Loaded module 'eventgrid' in 0.005 seconds. Loaded module 'eventhubs' in 0.010 seconds. Loaded module 'extension' in 0.003 seconds. Loaded module 'feedback' in 0.004 seconds. Loaded module 'find' in 0.005 seconds. Loaded module 'hdinsight' in 0.005 seconds. Loaded module 'interactive' in 0.001 seconds. Loaded module 'iot' in 0.006 seconds. Loaded module 'iotcentral' in 0.004 seconds. Loaded module 'keyvault' in 0.010 seconds. Loaded module 'kusto' in 0.006 seconds. Loaded module 'lab' in 0.006 seconds. Loaded module 'managedservices' in 0.004 seconds. Loaded module 'maps' in 0.004 seconds. Loaded module 'monitor' in 0.009 seconds. Loaded module 'natgateway' in 0.004 seconds. Event: CommandLoader.OnLoadCommandTable [] Loaded module 'netappfiles' in 0.027 seconds. Loaded module 'network' in 0.038 seconds. Loaded module 'policyinsights' in 0.009 seconds. Loaded module 'privatedns' in 0.009 seconds. Loaded module 'profile' in 0.004 seconds. Loaded module 'rdbms' in 0.012 seconds. Loaded module 'redis' in 0.007 seconds. Loaded module 'relay' in 0.007 seconds. Loaded module 'reservations' in 0.006 seconds. Loaded module 'resource' in 0.012 seconds. Loaded module 'role' in 0.008 seconds. Loaded module 'search' in 0.005 seconds. Loaded module 'security' in 0.005 seconds. Loaded module 'servicebus' in 0.008 seconds. Loaded module 'servicefabric' in 0.005 seconds. Loaded module 'signalr' in 0.004 seconds. Loaded module 'sql' in 0.011 seconds. Loaded module 'sqlvm' in 0.005 seconds. Event: CommandLoader.OnLoadCommandTable [] Loaded module 'storage' in 0.037 seconds. Loaded module 'vm' in 0.027 seconds. Loaded all modules in 0.547 seconds. (note: there's always an overhead with the first module loaded) Extensions directory: 'C:\Users\yunzh.azure\cliextensions' Event: CommandInvoker.OnPreCommandTableTruncate [<function AzCliLogging.init_command_file_logging at 0x03801C48>] az_command_data_logger : command args: bot facebook show --subscription {} --resource-group {} --name {} --with-secrets {} --debug metadata file logging enabled - writing logs to 'C:\Users\yunzh.azure\commands'. Event: CommandInvoker.OnPreArgumentLoad [<function register_global_subscription_argument..add_subscription_parameter at 0x03898270>] Event: CommandInvoker.OnPostArgumentLoad [] Event: CommandInvoker.OnPostCommandTableCreate [<function register_ids_argument..add_ids_arguments at 0x038BC5D0>, <function register_cache_arguments..add_cache_arguments at 0x038BC660>] Event: CommandInvoker.OnCommandTableLoaded [] Event: CommandInvoker.OnPreParseArgs [<function _documentdb_deprecate at 0x04566348>] Event: CommandInvoker.OnPostParseArgs [<function OutputProducer.handle_output_argument at 0x036CB6A8>, <function CLIQuery.handle_query_parameter at 0x03727780>, <function register_ids_argument..parse_ids_arguments at 0x038BC618>, <function handler at 0x0463B030>] Command group 'bot' is in preview. It may be changed/removed in a future release. Getting management service client client_type=AzureBotService msrest.universal_http.requests : Configuring retry: max_retries=4, backoff_factor=0.8, max_backoff=90 attempting to read file C:\Users\yunzh.azure\accessTokens.json as utf-8-sig adal-python : 6fee39ee-6c8f-4459-9243-01758d9ca5ed - Authority:Performing instance discovery: ... adal-python : 6fee39ee-6c8f-4459-9243-01758d9ca5ed - Authority:Performing static instance discovery adal-python : 6fee39ee-6c8f-4459-9243-01758d9ca5ed - Authority:Authority validated via static instance discovery adal-python : 6fee39ee-6c8f-4459-9243-01758d9ca5ed - TokenRequest:Getting token from cache with refresh if necessary. adal-python : 6fee39ee-6c8f-4459-9243-01758d9ca5ed - CacheDriver:finding with query keys: {'_clientId': '...', 'userId': '...'} adal-python : 6fee39ee-6c8f-4459-9243-01758d9ca5ed - CacheDriver:Looking for potential cache entries: {'_clientId': '...', 'userId': '...'} adal-python : 6fee39ee-6c8f-4459-9243-01758d9ca5ed - CacheDriver:Found 2 potential entries. adal-python : 6fee39ee-6c8f-4459-9243-01758d9ca5ed - CacheDriver:Resource specific token found. adal-python : 6fee39ee-6c8f-4459-9243-01758d9ca5ed - CacheDriver:Returning token from cache lookup, AccessTokenId: b'g1Hc8Wmwamzi6J6V7xe1jZc+t17iPHbhflSuy019Mpg=', RefreshTokenId: b'QGDy7UAu6R7NJ9pgcd10CT9tA1zfwabGEGKevPsk0fw=' adal-python : 6fee39ee-6c8f-4459-9243-01758d9ca5ed - CacheDriver:Cached token is expired at 2019-10-08 20:20:55.366059. Refreshing adal-python : 6fee39ee-6c8f-4459-9243-01758d9ca5ed - TokenRequest:called to refresh a token from the cache adal-python : 6fee39ee-6c8f-4459-9243-01758d9ca5ed - TokenRequest:Getting a new token from a refresh token urllib3.connectionpool : Starting new HTTPS connection (1): login.microsoftonline.com:443 urllib3.connectionpool : https://login.microsoftonline.com:443 "POST /6783970e-de9c-4878-a937-3b128b25f1ce/oauth2/token HTTP/1.1" 200 2590 adal-python : 6fee39ee-6c8f-4459-9243-01758d9ca5ed - OAuth2Client:Get Token Server returned this correlation_id: 6fee39ee-6c8f-4459-9243-01758d9ca5ed adal-python : 6fee39ee-6c8f-4459-9243-01758d9ca5ed - CacheDriver:Created new cache entry from refresh response. adal-python : 6fee39ee-6c8f-4459-9243-01758d9ca5ed - CacheDriver:Removing entry. adal-python : 6fee39ee-6c8f-4459-9243-01758d9ca5ed - CacheDriver:Adding entry AccessTokenId: b'9UBBZE9fsXytX8iLqvVeT1yMH8AhVmm7QnF5oGhjZ5s=', RefreshTokenId: b'yY3nM3cW5il3fSQ/gOt1rRYWiQ9acEz5bES04evG7Ik=' adal-python : 6fee39ee-6c8f-4459-9243-01758d9ca5ed - CacheDriver:Updating 1 cached refresh tokens adal-python : 6fee39ee-6c8f-4459-9243-01758d9ca5ed - CacheDriver:Remove many: 1 adal-python : 6fee39ee-6c8f-4459-9243-01758d9ca5ed - CacheDriver:Add many: 1 adal-python : 6fee39ee-6c8f-4459-9243-01758d9ca5ed - CacheDriver:Returning token refreshed after expiry. msrest.http_logger : Request URL: 'https://management.azure.com/subscriptions/subscriptionId/resourceGroups/resource-group/providers/Microsoft.BotService/botServices/resource-name/channels/FacebookChannel/listChannelWithKeys?api-version=2018-07-12' msrest.http_logger : Request method: 'POST' msrest.http_logger : Request headers: msrest.http_logger : 'Accept': 'application/json' msrest.http_logger : 'accept-language': 'en-US' msrest.http_logger : 'User-Agent': 'python/3.6.6 (Windows-10-10.0.18362-SP0) msrest/0.6.10 msrest_azure/0.6.1 azure-mgmt-botservice/0.2.0 Azure-SDK-For-Python AZURECLI/2.0.73' msrest.http_logger : Request body: msrest.http_logger : None msrest.universal_http : Configuring redirects: allow=True, max=30 msrest.universal_http : Configuring request: timeout=100, verify=True, cert=None msrest.universal_http : Configuring proxies: '' msrest.universal_http : Evaluate proxies against ENV settings: True urllib3.connectionpool : Starting new HTTPS connection (1): management.azure.com:443 urllib3.connectionpool : https://management.azure.com:443 "POST /subscriptions/subscriptionId/resourceGroups/resource-group/providers/Microsoft.BotService/botServices/resource-name/channels/FacebookChannel/listChannelWithKeys?api-version=2018-07-12 HTTP/1.1" 500 2522 urllib3.util.retry : Incremented Retry for (url='/subscriptions/subscriptionId/resourceGroups/resource-group/providers/Microsoft.BotService/botServices/resource-name/channels/FacebookChannel/listChannelWithKeys?api-version=2018-07-12'): Retry(total=3, connect=4, read=4, redirect=None, status=None) urllib3.connectionpool : Retry: /subscriptions/subscriptionId/resourceGroups/resource-group/providers/Microsoft.BotService/botServices/resource-name/channels/FacebookChannel/listChannelWithKeys?api-version=2018-07-12 urllib3.connectionpool : Resetting dropped connection: management.azure.com urllib3.connectionpool : https://management.azure.com:443 "POST /subscriptions/subscriptionId/resourceGroups/resource-group/providers/Microsoft.BotService/botServices/resource-name/channels/FacebookChannel/listChannelWithKeys?api-version=2018-07-12 HTTP/1.1" 500 2522 urllib3.util.retry : Incremented Retry for (url='/subscriptions/subscriptionId/resourceGroups/resource-group/providers/Microsoft.BotService/botServices/resource-name/channels/FacebookChannel/listChannelWithKeys?api-version=2018-07-12'): Retry(total=2, connect=4, read=4, redirect=None, status=None) urllib3.connectionpool : Retry: /subscriptions/subscriptionId/resourceGroups/resource-group/providers/Microsoft.BotService/botServices/resource-name/channels/FacebookChannel/listChannelWithKeys?api-version=2018-07-12 urllib3.connectionpool : Resetting dropped connection: management.azure.com urllib3.connectionpool : https://management.azure.com:443 "POST /subscriptions/subscriptionId/resourceGroups/resource-group/providers/Microsoft.BotService/botServices/resource-name/channels/FacebookChannel/listChannelWithKeys?api-version=2018-07-12 HTTP/1.1" 500 2522 urllib3.util.retry : Incremented Retry for (url='/subscriptions/subscriptionId/resourceGroups/resource-group/providers/Microsoft.BotService/botServices/resource-name/channels/FacebookChannel/listChannelWithKeys?api-version=2018-07-12'): Retry(total=1, connect=4, read=4, redirect=None, status=None) urllib3.connectionpool : Retry: /subscriptions/subscriptionId/resourceGroups/resource-group/providers/Microsoft.BotService/botServices/resource-name/channels/FacebookChannel/listChannelWithKeys?api-version=2018-07-12 urllib3.connectionpool : Resetting dropped connection: management.azure.com urllib3.connectionpool : https://management.azure.com:443 "POST /subscriptions/subscriptionId/resourceGroups/resource-group/providers/Microsoft.BotService/botServices/resource-name/channels/FacebookChannel/listChannelWithKeys?api-version=2018-07-12 HTTP/1.1" 500 2522 urllib3.util.retry : Incremented Retry for (url='/subscriptions/subscriptionId/resourceGroups/resource-group/providers/Microsoft.BotService/botServices/resource-name/channels/FacebookChannel/listChannelWithKeys?api-version=2018-07-12'): Retry(total=0, connect=4, read=4, redirect=None, status=None) urllib3.connectionpool : Retry: /subscriptions/subscriptionId/resourceGroups/resource-group/providers/Microsoft.BotService/botServices/resource-name/channels/FacebookChannel/listChannelWithKeys?api-version=2018-07-12 urllib3.connectionpool : Resetting dropped connection: management.azure.com urllib3.connectionpool : https://management.azure.com:443 "POST /subscriptions/subscriptionId/resourceGroups/resource-group/providers/Microsoft.BotService/botServices/resource-name/channels/FacebookChannel/listChannelWithKeys?api-version=2018-07-12 HTTP/1.1" 500 2522 msrest.exceptions : Error occurred in request., RetryError: HTTPSConnectionPool(host='management.azure.com', port=443): Max retries exceeded with url: /subscriptions/subscriptionId/resourceGroups/resource-group/providers/Microsoft.BotService/botServices/resource-name/channels/FacebookChannel/listChannelWithKeys?api-version=2018-07-12 (Caused by ResponseError('too many 500 error responses',)) cli.azure.cli.core.util : Error occurred in sending request. Please file an issue on https://github.com/Microsoft/botbuilder-tools/issues Error occurred in sending request. Please file an issue on https://github.com/Microsoft/botbuilder-tools/issues az_command_data_logger : exit code: 1 telemetry.save : Save telemetry record of length 2499 in cache telemetry.check : Returns Positive. telemetry.main : Begin creating telemetry upload process. telemetry.process : Creating upload process: "C:\Program Files (x86)\Microsoft SDKs\Azure\CLI2\python.exe C:\Program Files (x86)\Microsoft SDKs\Azure\CLI2\lib\site-packages\azure\cli\telemetry__init__.pyc C:\Users\yunzh.azure" telemetry.process : Return from creating process telemetry.main : Finish creating telemetry upload process. command ran in 26.374 seconds.

dmvtech commented 5 years ago

@eyunzhang My issue was related to an old token. Looks like yours might be as well.

Can you try:

az logout

az login

and if needed:

az account set --subscription <SUBSCRIPTION>

eyunzhang commented 5 years ago

no, I tried logout and re-login, same issue.

dmvtech commented 5 years ago

Does it fail with other channels as well (if applicable), or only Facebook?

dmvtech commented 5 years ago

hi @eyunzhang Can you confirm this is still happening? Does it fail on other channels other than Facebook?

dmvtech commented 5 years ago

I'm going to close this one assuming the issue no longer happens. Please let me know if that is not the case.