[BUG] Error upon trying to delete an offline device more than once

[CodeFinder2]

Describe the bug

Tried to delete a device that was offline. MQTT message correctly received by Z2M but Z2M itself failed to delete the device (would obviously need #107 here). I then pressed "REMOVE THIS DEVICE" a second time but then, nothing was send via MQTT (at least nothing MQTT related was logged by Z2M) and Z2MA showed the following error msg as web page

Zigbee2MqttAssistant 
Devices
Map
Status
Error.
An error occurred while processing your request.
Request ID: |39d49eb4-42117df3d0629982.

Development Mode
Swapping to Development environment will display more detailed information about the error that occurred.

The Development environment shouldn't be enabled for deployed applications. It can result in displaying sensitive information from exceptions to end users. For local debugging, enable the Development environment by setting the ASPNETCORE_ENVIRONMENT environment variable to Development and restarting the app.

© 2019 - Carl de Billy. Zigbee2Mqtt Assistant GITHUB Please report any problems or suggestions here.

To Reproduce

Steps to reproduce the behavior:

1. Start Z2M + Z2MA and go to a device-specific page.
2. Ensure that the device is offline (not sure if this is necessary for the bug to appear) and press "remove". I think its simply important that the removal fails in Z2M.
3. Nothing should happen (Z2M tries to delete the device unsuccessfully). Then press "REMOVE THIS DEVICE" again.
4. Z2MA shows the above output/error and with the log shown below and no MQTT msg is sent again. I can repeat this as often as I wish. Note that Z2MA does not (seem to) crash.

Expected behavior Send /remove MQTT message for every button click. (If Z2MA can receive feedback whether the removal was successful, it should be shown / indicated somewhere in Z2MA's UI (if possible).)

Installation

• Version of Zigbee2Mqtt: 1.8.0 (Coordinator version: 20190619)
• Version of Zigbee2MqttAssistant: 0.3.116 (0.3.116+Branch.master.Sha.65459f2613c2a7fdb4c9aa70c22153480daafc4d) Release
• Installation type (HASS.IO, Docker...): HASSIO
• Docker version + CPU type (amd64, arm arm64...): Odroid XU4 (arm)

Pertinent logs

Starting Zigbee2MqttAssistant v0.3.116+Branch.master.Sha.65459f2613c2a7fdb4c9aa70c22153480daafc4d...
warn: Microsoft.AspNetCore.DataProtection.KeyManagement.XmlKeyManager[35]
      No XML encryptor configured. Key {e0d8d9b4-813b-49f6-a3f4-e168fccab154} may be persisted to storage in unencrypted form.
Hosting environment: Production
Content root path: /app
Now listening on: http://[::]:80
Application started. Press Ctrl+C to shut down.

fail: Microsoft.AspNetCore.Diagnostics.ExceptionHandlerMiddleware[1]
      An unhandled exception has occurred while executing the request.
System.InvalidOperationException: Another remove in progress for this device.
   at Zigbee2MqttAssistant.Services.MqttConnectionService.RemoveDeviceAndWait(String deviceFriendlyName) in d:\a\1\s\Zigbee2MqttAssistant\Services\MqttConnectionService.cs:line 628
   at Zigbee2MqttAssistant.Services.BrigeOperationService.RemoveDeviceById(String deviceId) in d:\a\1\s\Zigbee2MqttAssistant\Services\BrigeOperationService.cs:line 27
   at Zigbee2MqttAssistant.Controllers.HomeController.RemoveDevice(String id) in d:\a\1\s\Zigbee2MqttAssistant\Controllers\HomeController.cs:line 123
   at Microsoft.AspNetCore.Mvc.Infrastructure.ActionMethodExecutor.TaskOfIActionResultExecutor.Execute(IActionResultTypeMapper mapper, ObjectMethodExecutor executor, Object controller, Object[] arguments)
   at Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.<InvokeActionMethodAsync>g__Awaited|12_0(ControllerActionInvoker invoker, ValueTask`1 actionResultValueTask)
   at Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.<InvokeNextActionFilterAsync>g__Awaited|10_0(ControllerActionInvoker invoker, Task lastTask, State next, Scope scope, Object state, Boolean isCompleted)
   at Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.Rethrow(ActionExecutedContextSealed context)
   at Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.Next(State& next, Scope& scope, Object& state, Boolean& isCompleted)
   at Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.InvokeInnerFilterAsync()
--- End of stack trace from previous location where exception was thrown ---
   at Microsoft.AspNetCore.Mvc.Infrastructure.ResourceInvoker.<InvokeNextResourceFilter>g__Awaited|24_0(ResourceInvoker invoker, Task lastTask, State next, Scope scope, Object state, Boolean isCompleted)
   at Microsoft.AspNetCore.Mvc.Infrastructure.ResourceInvoker.Rethrow(ResourceExecutedContextSealed context)
   at Microsoft.AspNetCore.Mvc.Infrastructure.ResourceInvoker.Next(State& next, Scope& scope, Object& state, Boolean& isCompleted)
   at Microsoft.AspNetCore.Mvc.Infrastructure.ResourceInvoker.InvokeFilterPipelineAsync()
--- End of stack trace from previous location where exception was thrown ---
   at Microsoft.AspNetCore.Mvc.Infrastructure.ResourceInvoker.<InvokeAsync>g__Awaited|17_0(ResourceInvoker invoker, Task task, IDisposable scope)
   at Microsoft.AspNetCore.Routing.EndpointMiddleware.<Invoke>g__AwaitRequestTask|6_0(Endpoint endpoint, Task requestTask, ILogger logger)
   at Microsoft.AspNetCore.Diagnostics.ExceptionHandlerMiddleware.<Invoke>g__Awaited|6_0(ExceptionHandlerMiddleware middleware, HttpContext context, Task task)

EDIT: when I restart Z2MA, it works again but only once.

[tdn131]

I confirm this bug. It's when trying to remove the device twice. The first attempt fails (according to the log of Zigbee2Mqtt). But the second attempt gives this error in Z2MA, but no actions are seen in the log of Z2M).

I have the same version of Z2MA (v0.3.116+Branch.master.Sha.65459f2613c2a7fdb4c9aa70c22153480daafc4d) and Z2M ('{"version":"1.8.0-dev","commit":"e63d196","coordinator":{"type":"zStack12","meta":{"transportrev":2,"product":0,"majorrel":2,"minorrel":6,"maintrel":3,"revision":20190608}},"log_level":"info","permit_join":false}'). This bug is also with the stable 1.8.0.

[carldebilly]

@CodeFinder2 @tdn131 Please try again with the last dev version.

[CodeFinder2]

No sorry, still not working for me (same behavior). However, I've not tried to force_remove yet to not lose my test case for this bug. 🙈

Z2MA Log:

Starting Zigbee2MqttAssistant v0.3.120+Branch.master.Sha.7156f1cd9db6a5d52a23fe5f927cfc5b9eabd467...
Hosting environment: Production
Content root path: /app
Now listening on: http://[::]:80
Application started. Press Ctrl+C to shut down.
fail: Microsoft.AspNetCore.Diagnostics.ExceptionHandlerMiddleware[1]
      An unhandled exception has occurred while executing the request.
System.InvalidOperationException: Another remove in progress for this device.
   at Zigbee2MqttAssistant.Services.MqttConnectionService.RemoveDeviceAndWait(String deviceFriendlyName, Boolean forceRemove) in d:\a\1\s\Zigbee2MqttAssistant\Services\MqttConnectionService.cs:line 666
   at Zigbee2MqttAssistant.Services.BrigeOperationService.RemoveDeviceById(String deviceId, Boolean forceRemove) in d:\a\1\s\Zigbee2MqttAssistant\Services\BrigeOperationService.cs:line 27
   at Zigbee2MqttAssistant.Controllers.HomeController.RemoveDevice(String id, Boolean forceRemove) in d:\a\1\s\Zigbee2MqttAssistant\Controllers\HomeController.cs:line 131
   at Microsoft.AspNetCore.Mvc.Infrastructure.ActionMethodExecutor.TaskOfIActionResultExecutor.Execute(IActionResultTypeMapper mapper, ObjectMethodExecutor executor, Object controller, Object[] arguments)
   at Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.<InvokeActionMethodAsync>g__Awaited|12_0(ControllerActionInvoker invoker, ValueTask`1 actionResultValueTask)
   at Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.<InvokeNextActionFilterAsync>g__Awaited|10_0(ControllerActionInvoker invoker, Task lastTask, State next, Scope scope, Object state, Boolean isCompleted)
   at Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.Rethrow(ActionExecutedContextSealed context)
   at Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.Next(State& next, Scope& scope, Object& state, Boolean& isCompleted)
   at Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.InvokeInnerFilterAsync()
--- End of stack trace from previous location where exception was thrown ---
   at Microsoft.AspNetCore.Mvc.Infrastructure.ResourceInvoker.<InvokeNextResourceFilter>g__Awaited|24_0(ResourceInvoker invoker, Task lastTask, State next, Scope scope, Object state, Boolean isCompleted)
   at Microsoft.AspNetCore.Mvc.Infrastructure.ResourceInvoker.Rethrow(ResourceExecutedContextSealed context)
   at Microsoft.AspNetCore.Mvc.Infrastructure.ResourceInvoker.Next(State& next, Scope& scope, Object& state, Boolean& isCompleted)
   at Microsoft.AspNetCore.Mvc.Infrastructure.ResourceInvoker.InvokeFilterPipelineAsync()
--- End of stack trace from previous location where exception was thrown ---
   at Microsoft.AspNetCore.Mvc.Infrastructure.ResourceInvoker.<InvokeAsync>g__Awaited|17_0(ResourceInvoker invoker, Task task, IDisposable scope)
   at Microsoft.AspNetCore.Routing.EndpointMiddleware.<Invoke>g__AwaitRequestTask|6_0(Endpoint endpoint, Task requestTask, ILogger logger)
   at Microsoft.AspNetCore.Diagnostics.ExceptionHandlerMiddleware.<Invoke>g__Awaited|6_0(ExceptionHandlerMiddleware middleware, HttpContext context, Task task)

Z2M Log (excerpt):

zigbee2mqtt:info  2019-12-30 11:33:20: Removing '0x00124b0006227235'
zigbee2mqtt:info  2019-12-30 11:33:27: Starting network scan (includeRoutes 'false')
zigbee2mqtt:error 2019-12-30 11:33:30: Failed to remove 0x00124b0006227235 (Error: AREQ - ZDO - mgmtLeaveRsp after 10000ms)
zigbee2mqtt:error 2019-12-30 11:33:30: See https://www.zigbee2mqtt.io/information/mqtt_topics_and_message_structure.html#zigbee2mqttbridgeconfigremove for more info

(pressed remove twice)

[carldebilly]

Ooops my bad. I made my test with a custom version of Z2M !!

Will work when this PR will get merged: https://github.com/Koenkk/zigbee2mqtt/pull/2636

[CodeFinder2]

No worries and thank you very much for your quick efforts! :-) Looks great!

[carldebilly]

@CodeFinder2 PR Koenkk/zigbee2mqtt#2636 has been merged!

Please test it with the edge/dev branch of Z2M.

[CodeFinder2]

Sorry, just tested this with:

zigbee2mqtt:info  2020-01-10 11:45:47: Starting zigbee2mqtt version 1.8.0-dev (commit #2451d536f2c9e446d396df55c9493f256ab9352e)
zigbee2mqtt:info  2020-01-10 11:45:47: Starting zigbee-herdsman...
zigbee2mqtt:info  2020-01-10 11:45:49: zigbee-herdsman started
zigbee2mqtt:info  2020-01-10 11:45:49: Coordinator firmware version: '{"type":"zStack12","meta":{"transportrev":2,"product":0,"majorrel":2,"minorrel":6,"maintrel":3,"revision":20190619}}'
zigbee2mqtt:info  2020-01-10 11:45:49: Currently 40 devices are joined: [...]

...and it's not working (same error/behavior). I've (re-) installed the latest zigbee2mqtt-edge Hassio plugin so I should be using the latest dev version...

~~ However, I was not able to find the commit hash in Z2M repo so I am not sure whether I am really using the latest version that already includes your PR against dev branch... 🤔 ~~

EDIT: oh my fault, the commit hash, of course, points to the hassio addon of Z2M; that's why I was not able to find it in the Z2M repo. There seem's to be a bug in the hassio addon in a sense that I was not able to update to the latest dev/edge version. See https://github.com/danielwelch/hassio-zigbee2mqtt/issues/284

[carldebilly]

Nope Z2M HASS.IO edge is not up to date yet... you'll need to test it directly with Z2M container.

[CodeFinder2]

Okay, once again: tested with latest Z2MA v0.3.125 (dev, hassio addon) and Z2M was at 15d984e (latest as of know), dev branch, but it's still not working, got a:

Zigbee2MqttAssistant 
Devices
Map
Status
Error.
An error occurred while processing your request.
Request ID: |d3c03035-4c9dc94d66901044.

Development Mode
Swapping to Development environment will display more detailed information about the error that occurred.

The Development environment shouldn't be enabled for deployed applications. It can result in displaying sensitive information from exceptions to end users. For local debugging, enable the Development environment by setting the ASPNETCORE_ENVIRONMENT environment variable to Development and restarting the app.

© 2019 - Carl de Billy. Zigbee2Mqtt Assistant GITHUB Please report any problems or suggestions here.

Z2M log:

zigbee2mqtt:info  2020-01-11 17:53:42: Starting network scan (includeRoutes 'false')
zigbee2mqtt:info  2020-01-11 17:53:47: Removing '0x00124b0006227235'
zigbee2mqtt:error 2020-01-11 17:53:57: Failed to remove 0x00124b0006227235 (Error: AREQ - ZDO - mgmtLeaveRsp after 10000ms)
zigbee2mqtt:error 2020-01-11 17:53:57: See https://www.zigbee2mqtt.io/information/mqtt_topics_and_message_structure.html#zigbee2mqttbridgeconfigremove for more info
zigbee2mqtt:info  2020-01-11 17:53:57: MQTT publish: topic 'zigbee2mqtt/bridge/log', payload '{"type":"device_removed_failed","message":"0x00124b0006227235"}'

Z2MA log:

Log
Starting Zigbee2MqttAssistant v0.3.125+Branch.master.Sha.3cfbab9227121fb173c81c7cb5e5c741b6ad68d0...
warn: Microsoft.AspNetCore.DataProtection.KeyManagement.XmlKeyManager[35]
      No XML encryptor configured. Key {476f27d0-4949-4870-a9d4-7dadd61354ec} may be persisted to storage in unencrypted form.
Hosting environment: Production
Content root path: /app
Now listening on: http://[::]:80
Application started. Press Ctrl+C to shut down.
fail: Microsoft.AspNetCore.Antiforgery.DefaultAntiforgery[7]
      An exception was thrown while deserializing the token.
Microsoft.AspNetCore.Antiforgery.AntiforgeryValidationException: The antiforgery token could not be decrypted.
 ---> System.Security.Cryptography.CryptographicException: The key {bb763c15-4de0-41d2-9d78-305b7554c15e} was not found in the key ring.
   at Microsoft.AspNetCore.DataProtection.KeyManagement.KeyRingBasedDataProtector.UnprotectCore(Byte[] protectedData, Boolean allowOperationsOnRevokedKeys, UnprotectStatus& status)
   at Microsoft.AspNetCore.DataProtection.KeyManagement.KeyRingBasedDataProtector.DangerousUnprotect(Byte[] protectedData, Boolean ignoreRevocationErrors, Boolean& requiresMigration, Boolean& wasRevoked)
   at Microsoft.AspNetCore.DataProtection.KeyManagement.KeyRingBasedDataProtector.Unprotect(Byte[] protectedData)
   at Microsoft.AspNetCore.Antiforgery.DefaultAntiforgeryTokenSerializer.Deserialize(String serializedToken)
   --- End of inner exception stack trace ---
   at Microsoft.AspNetCore.Antiforgery.DefaultAntiforgeryTokenSerializer.Deserialize(String serializedToken)
   at Microsoft.AspNetCore.Antiforgery.DefaultAntiforgery.GetCookieTokenDoesNotThrow(HttpContext httpContext)
fail: Microsoft.AspNetCore.Diagnostics.ExceptionHandlerMiddleware[1]
      An unhandled exception has occurred while executing the request.
System.Exception: Remove device failed.
   at Zigbee2MqttAssistant.Services.MqttConnectionService.RemoveDeviceAndWait(String deviceFriendlyName, Boolean forceRemove) in d:\a\1\s\Zigbee2MqttAssistant\Services\MqttConnectionService.cs:line 676
   at Zigbee2MqttAssistant.Services.BrigeOperationService.RemoveDeviceById(String deviceId, Boolean forceRemove) in d:\a\1\s\Zigbee2MqttAssistant\Services\BrigeOperationService.cs:line 27
   at Zigbee2MqttAssistant.Controllers.HomeController.RemoveDevice(String id, Boolean forceRemove) in d:\a\1\s\Zigbee2MqttAssistant\Controllers\HomeController.cs:line 131
   at Microsoft.AspNetCore.Mvc.Infrastructure.ActionMethodExecutor.TaskOfIActionResultExecutor.Execute(IActionResultTypeMapper mapper, ObjectMethodExecutor executor, Object controller, Object[] arguments)
   at Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.<InvokeActionMethodAsync>g__Awaited|12_0(ControllerActionInvoker invoker, ValueTask`1 actionResultValueTask)
   at Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.<InvokeNextActionFilterAsync>g__Awaited|10_0(ControllerActionInvoker invoker, Task lastTask, State next, Scope scope, Object state, Boolean isCompleted)
   at Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.Rethrow(ActionExecutedContextSealed context)
   at Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.Next(State& next, Scope& scope, Object& state, Boolean& isCompleted)
   at Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.<InvokeInnerFilterAsync>g__Awaited|13_0(ControllerActionInvoker invoker, Task lastTask, State next, Scope scope, Object state, Boolean isCompleted)
   at Microsoft.AspNetCore.Mvc.Infrastructure.ResourceInvoker.<InvokeNextResourceFilter>g__Awaited|24_0(ResourceInvoker invoker, Task lastTask, State next, Scope scope, Object state, Boolean isCompleted)
   at Microsoft.AspNetCore.Mvc.Infrastructure.ResourceInvoker.Rethrow(ResourceExecutedContextSealed context)
   at Microsoft.AspNetCore.Mvc.Infrastructure.ResourceInvoker.Next(State& next, Scope& scope, Object& state, Boolean& isCompleted)
   at Microsoft.AspNetCore.Mvc.Infrastructure.ResourceInvoker.<InvokeFilterPipelineAsync>g__Awaited|19_0(ResourceInvoker invoker, Task lastTask, State next, Scope scope, Object state, Boolean isCompleted)
   at Microsoft.AspNetCore.Mvc.Infrastructure.ResourceInvoker.<InvokeAsync>g__Awaited|17_0(ResourceInvoker invoker, Task task, IDisposable scope)
   at Microsoft.AspNetCore.Routing.EndpointMiddleware.<Invoke>g__AwaitRequestTask|6_0(Endpoint endpoint, Task requestTask, ILogger logger)
   at Microsoft.AspNetCore.Diagnostics.ExceptionHandlerMiddleware.<Invoke>g__Awaited|6_0(ExceptionHandlerMiddleware middleware, HttpContext context, Task task)

Also checked git log and your commit cabb1f3 was in my tree. It seemed to show the above error when Z2M replied with the "device_removed_failed"...

EDIT: tried a 2nd time and now Z2MA seemed to crash w/o any log/output. Also, Z2M did not noticed anything MQTT related from Z2MA... (unfortunately, cannot reproduce this at the moment so we may ignore it for now).

EDIT2: tried 2 more times and I got the same behavior as described in the beginning of this post. Log:

Starting Zigbee2MqttAssistant v0.3.125+Branch.master.Sha.3cfbab9227121fb173c81c7cb5e5c741b6ad68d0...
Hosting environment: Production
Content root path: /app
Now listening on: http://[::]:80
Application started. Press Ctrl+C to shut down.
fail: Microsoft.AspNetCore.Diagnostics.ExceptionHandlerMiddleware[1]
      An unhandled exception has occurred while executing the request.
System.Exception: Remove device failed.
   at Zigbee2MqttAssistant.Services.MqttConnectionService.RemoveDeviceAndWait(String deviceFriendlyName, Boolean forceRemove) in d:\a\1\s\Zigbee2MqttAssistant\Services\MqttConnectionService.cs:line 676
   at Zigbee2MqttAssistant.Services.BrigeOperationService.RemoveDeviceById(String deviceId, Boolean forceRemove) in d:\a\1\s\Zigbee2MqttAssistant\Services\BrigeOperationService.cs:line 27
   at Zigbee2MqttAssistant.Controllers.HomeController.RemoveDevice(String id, Boolean forceRemove) in d:\a\1\s\Zigbee2MqttAssistant\Controllers\HomeController.cs:line 131
   at Microsoft.AspNetCore.Mvc.Infrastructure.ActionMethodExecutor.TaskOfIActionResultExecutor.Execute(IActionResultTypeMapper mapper, ObjectMethodExecutor executor, Object controller, Object[] arguments)
   at Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.<InvokeActionMethodAsync>g__Awaited|12_0(ControllerActionInvoker invoker, ValueTask`1 actionResultValueTask)
   at Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.<InvokeNextActionFilterAsync>g__Awaited|10_0(ControllerActionInvoker invoker, Task lastTask, State next, Scope scope, Object state, Boolean isCompleted)
   at Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.Rethrow(ActionExecutedContextSealed context)
   at Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.Next(State& next, Scope& scope, Object& state, Boolean& isCompleted)
   at Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.<InvokeInnerFilterAsync>g__Awaited|13_0(ControllerActionInvoker invoker, Task lastTask, State next, Scope scope, Object state, Boolean isCompleted)
   at Microsoft.AspNetCore.Mvc.Infrastructure.ResourceInvoker.<InvokeNextResourceFilter>g__Awaited|24_0(ResourceInvoker invoker, Task lastTask, State next, Scope scope, Object state, Boolean isCompleted)
   at Microsoft.AspNetCore.Mvc.Infrastructure.ResourceInvoker.Rethrow(ResourceExecutedContextSealed context)
   at Microsoft.AspNetCore.Mvc.Infrastructure.ResourceInvoker.Next(State& next, Scope& scope, Object& state, Boolean& isCompleted)
   at Microsoft.AspNetCore.Mvc.Infrastructure.ResourceInvoker.<InvokeFilterPipelineAsync>g__Awaited|19_0(ResourceInvoker invoker, Task lastTask, State next, Scope scope, Object state, Boolean isCompleted)
   at Microsoft.AspNetCore.Mvc.Infrastructure.ResourceInvoker.<InvokeAsync>g__Awaited|17_0(ResourceInvoker invoker, Task task, IDisposable scope)
   at Microsoft.AspNetCore.Routing.EndpointMiddleware.<Invoke>g__AwaitRequestTask|6_0(Endpoint endpoint, Task requestTask, ILogger logger)
   at Microsoft.AspNetCore.Diagnostics.ExceptionHandlerMiddleware.<Invoke>g__Awaited|6_0(ExceptionHandlerMiddleware middleware, HttpContext context, Task task)

Also very strange: in my 3rd try, Z2M again replied with a "device_removed_failed" but the device disappeared in Z2MA's device list. I then restarted Z2MA and it was back there again. Note that for every try, the logs of Z2M was (also) always the same.

[carldebilly]

Ok the real problem here is there:

zigbee2mqtt:info  2020-01-11 17:53:47: Removing '0x00124b0006227235'
zigbee2mqtt:error 2020-01-11 17:53:57: Failed to remove 0x00124b0006227235 (Error: AREQ - ZDO - mgmtLeaveRsp after 10000ms)

Maybe you should try a force remove. The recent improvements in Z2MA is to:

1. allow you to issue a force remove (new feature)
2. don't crash when you try a second time because it was waiting for the result of the first time.

Z2MA won't fix the problem, it will just react more nicely to it :-).

[carldebilly]

@all-contributors please add codefinder2 to bugs

[allcontributors[bot]]

@carldebilly

I've put up a pull request to add @codefinder2! :tada:

[CodeFinder2]

Ok the real problem here is there:

zigbee2mqtt:info  2020-01-11 17:53:47: Removing '0x00124b0006227235'
zigbee2mqtt:error 2020-01-11 17:53:57: Failed to remove 0x00124b0006227235 (Error: AREQ - ZDO - mgmtLeaveRsp after 10000ms)

Maybe you should try a force remove. The recent improvements in Z2MA is to:

1. allow you to issue a force remove (new feature)
2. don't crash when you try a second time because it was waiting for the result of the first time.

Z2MA won't fix the problem, it will just react more nicely to it :-).

I know that Z2MA cannot fix the problem of not being able to (actually) remove the device and, yes, doing a force_remove would do the trick here. :see_no_evil: However, I would assume that I won't get a "crash info page" after clicking "REMOVE" in Z2MA, regardless of how often I click on that button. And I observed that even after clicking it once, I get the crash info page as quoted above. To me it seemed, Z2MA was unable to process the returned "device_removed_failed" correctly.

Do you agree that this should be handled more properly wrt. "just react more nicely"? :see_no_evil:

In other words: I would have assumed to get a decent message on that page stating something like "ignored: removal in progress, please wait..." when I click the REMOVE button and the previous remove operation is still in progress (= no response from Z2M via MQTT yet). Once the removal finished successfully (cannot be the case for my test case in this issue ;-) ), I would assume to see something like "removal succeeded". And finally, if the removal failed, something like "removal failed" (ideally, we can add some more info about "why" given Z2M's response) should be displayed inside the "remove device section".

However, in my (test) case, the entire pages change to:

Zigbee2MqttAssistant 
Devices
Map
Status
Error.
An error occurred while processing your request.
Request ID: |d3c03035-4c9dc94d66901044.

Development Mode
Swapping to Development environment will display more detailed information about the error that occurred.

The Development environment shouldn't be enabled for deployed applications. It can result in displaying sensitive information from exceptions to end users. For local debugging, enable the Development environment by setting the ASPNETCORE_ENVIRONMENT environment variable to Development and restarting the app.

© 2019 - Carl de Billy. Zigbee2Mqtt Assistant GITHUB Please report any problems or suggestions here.

Is this what you expect Z2MA to show when unsuccessfully deleting devices many times (not forcefully)?

Hope this makes it easier to understand :-)

[carldebilly]

I agree it would be a better experience... before you were required to restart Z2MA, so it's an improvement, but there's a lot of potential improvement remaining, I totally agree on this :-)

[CodeFinder2]

Hmm. After the above error (i.e., after receiving the device_removed_failed which causes Z2MA to show the previously quoted page), I still have to restart Z2MA again to allow pressing the button. If not, I immediately get the above error... :thinking:

[carldebilly]

Seriously? :'(

[CodeFinder2]

Yes 😕, but let me test this again and report back first...

[CodeFinder2]

Tested again, commit #7d26873 (latest):

1. Started Z2M.
2. Started Z2MA v0.3.131.
3. Ensured that Z2M is working fine (switch on and off a light). MQTT connections are up as well.
4. Pressed "REMOVE THIS DEVICE" (once) and waited.
5. Z2M reacted with (as quoted earlier / above) "Removing '0x0012...'", etc. (correct).
6. When Z2M failed with device_remove_failed (to topic zigbee2mqtt/bridge/log), Z2MA immediately showed the error page quoted above: "Error. An error occurred while processing your request. Request ID: |edf08aad-45976a92953ffea8. [...]".
7. Z2MA was still running though. The already quoted exception was written to the log: "[...] System.Exception: Remove device failed. [...]"
8. If I reload the Z2MA page to get rid of that error page, I can go to the device to be deleted again.
9. If I press "REMOVE THIS DEVICE" again, Z2M reacts with "Removing..." (this is good and I cannot remember seeing this previously :see_no_evil: ).
10. However, when Z2M finally fails to do the (2nd) deletion and acknowledges this by sending "device_remove_failed", Z2MA shows the error page (see step 6) again.
11. I then reloaded the page and interesstingly, Z2MA REMOVED the device from its device list (although it couldn't have been deleted from Z2M, as stated above).
12. I reloaded a 2nd time, and the device is listed again (huh?!) but with the info "NO COMPONENTS Maybe this device is not (yet) supported by Zigbee2Mqtt?". Reloading the page again (and again ...) didn't change anything.
13. I did the removal a third time (like explained above) and it showed the same behavior (error page). However, I was not able to list the device again by reloading the page (tried > 1x).
14. During all these tests, Z2MA only showed the already quoted "System.Exception: Remove device failed." (which appear correct to me).
15. After restarting Z2MA, the device was listed again. After trying to remove it a 4th time, the same happend as explained in the prev. keypoints (except that the device disappeared in the list w/o being able to list it again by reloading).

So yeah, sorry, but still seems faulty somehow :disappointed: ... or is this intended behavior? :smile:

PS: Hope this is not too verbose. I tried to explain it as detailed as possible to help you debugging it.

[SPEC1AL1ST]

I see this bug now again

[denykk]

confirm the same error

[FlorinAcsinte]

Receiving same problem:

fail: Microsoft.AspNetCore.Diagnostics.ExceptionHandlerMiddleware[1]
      An unhandled exception has occurred while executing the request.
System.InvalidOperationException: Another remove in progress for this device.
   at Zigbee2MqttAssistant.Services.MqttConnectionService.RemoveDeviceAndWait(String deviceFriendlyName, Boolean forceRemove) in d:\a\1\s\Zigbee2MqttAssistant\Services\MqttConnectionService.cs:line 744
   at Zigbee2MqttAssistant.Services.BrigeOperationService.RemoveDeviceById(String deviceId, Boolean forceRemove) in d:\a\1\s\Zigbee2MqttAssistant\Services\BrigeOperationService.cs:line 27
   at Zigbee2MqttAssistant.Controllers.HomeController.RemoveDevice(String id, Boolean forceRemove) in d:\a\1\s\Zigbee2MqttAssistant\Controllers\HomeController.cs:line 110
   at Microsoft.AspNetCore.Mvc.Infrastructure.ActionMethodExecutor.TaskOfIActionResultExecutor.Execute(IActionResultTypeMapper mapper, ObjectMethodExecutor executor, Object controller, Object[] arguments)
   at Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.<InvokeActionMethodAsync>g__Awaited|12_0(ControllerActionInvoker invoker, ValueTask`1 actionResultValueTask)
   at Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.<InvokeNextActionFilterAsync>g__Awaited|10_0(ControllerActionInvoker invoker, Task lastTask, State next, Scope scope, Object state, Boolean isCompleted)
   at Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.Rethrow(ActionExecutedContextSealed context)
   at Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.Next(State& next, Scope& scope, Object& state, Boolean& isCompleted)
   at Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.<InvokeInnerFilterAsync>g__Awaited|13_0(ControllerActionInvoker invoker, Task lastTask, State next, Scope scope, Object state, Boolean isCompleted)
   at Microsoft.AspNetCore.Mvc.Infrastructure.ResourceInvoker.<InvokeNextResourceFilter>g__Awaited|24_0(ResourceInvoker invoker, Task lastTask, State next, Scope scope, Object state, Boolean isCompleted)
   at Microsoft.AspNetCore.Mvc.Infrastructure.ResourceInvoker.Rethrow(ResourceExecutedContextSealed context)
   at Microsoft.AspNetCore.Mvc.Infrastructure.ResourceInvoker.Next(State& next, Scope& scope, Object& state, Boolean& isCompleted)
   at Microsoft.AspNetCore.Mvc.Infrastructure.ResourceInvoker.<InvokeFilterPipelineAsync>g__Awaited|19_0(ResourceInvoker invoker, Task lastTask, State next, Scope scope, Object state, Boolean isCompleted)
   at Microsoft.AspNetCore.Mvc.Infrastructure.ResourceInvoker.<InvokeAsync>g__Awaited|17_0(ResourceInvoker invoker, Task task, IDisposable scope)
   at Microsoft.AspNetCore.Routing.EndpointMiddleware.<Invoke>g__AwaitRequestTask|6_0(Endpoint endpoint, Task requestTask, ILogger logger)
   at Microsoft.AspNetCore.Diagnostics.ExceptionHandlerMiddleware.<Invoke>g__Awaited|6_0(ExceptionHandlerMiddleware middleware, HttpContext context, Task task)
fail: Microsoft.AspNetCore.Diagnostics.ExceptionHandlerMiddleware[1]
      An unhandled exception has occurred while executing the request.
System.InvalidOperationException: Another remove in progress for this device.
   at Zigbee2MqttAssistant.Services.MqttConnectionService.RemoveDeviceAndWait(String deviceFriendlyName, Boolean forceRemove) in d:\a\1\s\Zigbee2MqttAssistant\Services\MqttConnectionService.cs:line 744
   at Zigbee2MqttAssistant.Services.BrigeOperationService.RemoveDeviceById(String deviceId, Boolean forceRemove) in d:\a\1\s\Zigbee2MqttAssistant\Services\BrigeOperationService.cs:line 27
   at Zigbee2MqttAssistant.Controllers.HomeController.RemoveDevice(String id, Boolean forceRemove) in d:\a\1\s\Zigbee2MqttAssistant\Controllers\HomeController.cs:line 110
   at Microsoft.AspNetCore.Mvc.Infrastructure.ActionMethodExecutor.TaskOfIActionResultExecutor.Execute(IActionResultTypeMapper mapper, ObjectMethodExecutor executor, Object controller, Object[] arguments)
   at Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.<InvokeActionMethodAsync>g__Awaited|12_0(ControllerActionInvoker invoker, ValueTask`1 actionResultValueTask)
   at Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.<InvokeNextActionFilterAsync>g__Awaited|10_0(ControllerActionInvoker invoker, Task lastTask, State next, Scope scope, Object state, Boolean isCompleted)
   at Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.Rethrow(ActionExecutedContextSealed context)
   at Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.Next(State& next, Scope& scope, Object& state, Boolean& isCompleted)
   at Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.InvokeInnerFilterAsync()
--- End of stack trace from previous location where exception was thrown ---
   at Microsoft.AspNetCore.Mvc.Infrastructure.ResourceInvoker.<InvokeNextResourceFilter>g__Awaited|24_0(ResourceInvoker invoker, Task lastTask, State next, Scope scope, Object state, Boolean isCompleted)
   at Microsoft.AspNetCore.Mvc.Infrastructure.ResourceInvoker.Rethrow(ResourceExecutedContextSealed context)
   at Microsoft.AspNetCore.Mvc.Infrastructure.ResourceInvoker.Next(State& next, Scope& scope, Object& state, Boolean& isCompleted)
   at Microsoft.AspNetCore.Mvc.Infrastructure.ResourceInvoker.InvokeFilterPipelineAsync()
--- End of stack trace from previous location where exception was thrown ---
   at Microsoft.AspNetCore.Mvc.Infrastructure.ResourceInvoker.<InvokeAsync>g__Awaited|17_0(ResourceInvoker invoker, Task task, IDisposable scope)
   at Microsoft.AspNetCore.Routing.EndpointMiddleware.<Invoke>g__AwaitRequestTask|6_0(Endpoint endpoint, Task requestTask, ILogger logger)
   at Microsoft.AspNetCore.Diagnostics.ExceptionHandlerMiddleware.<Invoke>g__Awaited|6_0(ExceptionHandlerMiddleware middleware, HttpContext context, Task task)

Getting this after running 'foce remove' twice (doesn't seem to force remove the device :( )