Repository: postlund/pyatv

Issue:
pyatv implicitly logged out, logging in again
By a coincidence I was looking through my logs of home-assistant and saw that the same message was spammed over and over again. I will start by removing the remote from apple tv and add again. I have the second or third gen apple tv.

The message is repeated about 12 times every second which doesn't seem like a good behaviour. Some kind of delay should be introduced somewhere?

```log
2021-04-03 13:00:15 INFO (MainThread) [pyatv.dmap.daap] Logged in and got session id 232771202
2021-04-03 13:00:15 DEBUG (MainThread) [pyatv.dmap] Playstatus error occurred: failed to login: 406
2021-04-03 13:00:15 DEBUG (MainThread) [pyatv.dmap] Waiting for playstatus updates
2021-04-03 13:00:15 DEBUG (MainThread) [pyatv.dmap.daap] Already logged in, re-using seasion id 232771202
2021-04-03 13:00:15 DEBUG (MainThread) [pyatv.support.net] GET URL: http://192.168.100.28:3689/ctrl-int/1/playstatusupdate?session-id=232771202&revision-number=214
2021-04-03 13:00:15 WARNING (MainThread) [homeassistant.components.apple_tv.media_player] A <class 'pyatv.exceptions.AuthenticationError'> error occurred: failed to login: 406
2021-04-03 13:00:15 DEBUG (MainThread) [pyatv.support.net] Response: status=403, headers=[Date=Sat, 03 Apr 2021 10:48:50 GMT, DAAP-Server=iTunes/11.1b37 (OS X), Content-Type=application/x-dmap-tagged, Content-Length=0]
2021-04-03 13:00:15 DEBUG (MainThread) [pyatv.support.net] << GET (Data=)
2021-04-03 13:00:15 DEBUG (MainThread) [pyatv.dmap.daap]
2021-04-03 13:00:15 INFO (MainThread) [pyatv.dmap.daap] implicitly logged out, logging in again
2021-04-03 13:00:15 DEBUG (MainThread) [pyatv.support.net] GET URL: http://192.168.100.28:3689/login?pairing-guid=0x4A5861992AC66A69&hasFP=1
2021-04-03 13:00:15 DEBUG (MainThread) [pyatv.support.net] Response: status=200, headers=[Date=Sat, 03 Apr 2021 10:48:50 GMT, DAAP-Server=iTunes/11.1b37 (OS X), Content-Type=application/x-dmap-tagged, Content-Length=47, Content-Encoding=gzip]
2021-04-03 13:00:15 DEBUG (MainThread) [pyatv.support.net] << GET (Data=6d6c6f67000000186d73747400000004000000c86d6c69640000000472aa6ea3)
2021-04-03 13:00:15 DEBUG (MainThread) [pyatv.dmap.daap] mlog: [container, dmap.loginresponse]
  mstt: 200 [uint, dmap.status]
  mlid: 1923772067 [uint, dmap.sessionid]

2021-04-03 13:00:15 INFO (MainThread) [pyatv.dmap.daap] Logged in and got session id 1923772067
2021-04-03 13:00:15 DEBUG (MainThread) [pyatv.support.net] GET URL: http://192.168.100.28:3689/ctrl-int/1/playstatusupdate?session-id=1923772067&revision-number=214
2021-04-03 13:00:15 DEBUG (MainThread) [pyatv.support.net] Response: status=403, headers=[Date=Sat, 03 Apr 2021 10:48:50 GMT, DAAP-Server=iTunes/11.1b37 (OS X), Content-Type=application/x-dmap-tagged, Content-Length=0]
2021-04-03 13:00:15 DEBUG (MainThread) [pyatv.support.net] << GET (Data=)
2021-04-03 13:00:15 DEBUG (MainThread) [pyatv.dmap.daap]
2021-04-03 13:00:15 INFO (MainThread) [pyatv.dmap.daap] implicitly logged out, logging in again
2021-04-03 13:00:15 DEBUG (MainThread) [pyatv.support.net] GET URL: http://192.168.100.28:3689/login?pairing-guid=0x4A5861992AC66A69&hasFP=1
2021-04-03 13:00:15 DEBUG (MainThread) [pyatv.support.net] Response: status=200, headers=[Date=Sat, 03 Apr 2021 10:48:50 GMT, DAAP-Server=iTunes/11.1b37 (OS X), Content-Type=application/x-dmap-tagged, Content-Length=47, Content-Encoding=gzip]
2021-04-03 13:00:15 DEBUG (MainThread) [pyatv.support.net] << GET (Data=6d6c6f67000000186d73747400000004000000c86d6c6964000000046ce97f80)
2021-04-03 13:00:15 DEBUG (MainThread) [pyatv.dmap.daap] mlog: [container, dmap.loginresponse]
  mstt: 200 [uint, dmap.status]
  mlid: 1827241856 [uint, dmap.sessionid]

2021-04-03 13:00:15 INFO (MainThread) [pyatv.dmap.daap] Logged in and got session id 1827241856
2021-04-03 13:00:15 DEBUG (MainThread) [pyatv.dmap] Playstatus error occurred: failed to login: 403
2021-04-03 13:00:15 DEBUG (MainThread) [pyatv.dmap] Waiting for playstatus updates
2021-04-03 13:00:15 DEBUG (MainThread) [pyatv.dmap.daap] Already logged in, re-using seasion id 1827241856
2021-04-03 13:00:15 DEBUG (MainThread) [pyatv.support.net] GET URL: http://192.168.100.28:3689/ctrl-int/1/playstatusupdate?session-id=1827241856&revision-number=214
2021-04-03 13:00:15 WARNING (MainThread) [homeassistant.components.apple_tv.media_player] A <class 'pyatv.exceptions.AuthenticationError'> error occurred: failed to login: 403
2021-04-03 13:00:15 DEBUG (MainThread) [pyatv.support.net] Response: status=403, headers=[Date=Sat, 03 Apr 2021 10:48:50 GMT, DAAP-Server=iTunes/11.1b37 (OS X), Content-Type=application/x-dmap-tagged, Content-Length=0]
2021-04-03 13:00:15 DEBUG (MainThread) [pyatv.support.net] << GET (Data=)
2021-04-03 13:00:15 DEBUG (MainThread) [pyatv.dmap.daap]
2021-04-03 13:00:15 INFO (MainThread) [pyatv.dmap.daap] implicitly logged out, logging in again
2021-04-03 13:00:15 DEBUG (MainThread) [pyatv.support.net] GET URL: http://192.168.100.28:3689/login?pairing-guid=0x4A5861992AC66A69&hasFP=1
2021-04-03 13:00:15 DEBUG (MainThread) [pyatv.support.net] Response: status=200, headers=[Date=Sat, 03 Apr 2021 10:48:50 GMT, DAAP-Server=iTunes/11.1b37 (OS X), Content-Type=application/x-dmap-tagged, Content-Length=47, Content-Encoding=gzip]
2021-04-03 13:00:15 DEBUG (MainThread) [pyatv.support.net] << GET (Data=6d6c6f67000000186d73747400000004000000c86d6c69640000000407f4b112)
2021-04-03 13:00:15 DEBUG (MainThread) [pyatv.dmap.daap] mlog: [container, dmap.loginresponse]
  mstt: 200 [uint, dmap.status]
  mlid: 133476626 [uint, dmap.sessionid]
```
**To Reproduce**
Don't know

**Expected behavior**

**System Setup (please complete the following information):**
 - OS: Centos 8 using docker-ce with latest home-assistant/stable
 - Python: home-assistant/stable
 - pyatv: [e.g. 0.3.10]
- Apple TV: gen 2/3

**Additional context**


Discussion:
codecov[bot]: # [Codecov](https://codecov.io/gh/postlund/pyatv/pull/1004?src=pr&el=h1) Report
> Merging [#1004](https://codecov.io/gh/postlund/pyatv/pull/1004?src=pr&el=desc) (225966f) into [master](https://codecov.io/gh/postlund/pyatv/commit/f0f7eaf64c824d40ba72ef727ffb37ea87979f25?el=desc) (f0f7eaf) will **increase** coverage by `0.27%`.
> The diff coverage is `97.42%`.

[![Impacted file tree graph](https://codecov.io/gh/postlund/pyatv/pull/1004/graphs/tree.svg?width=650&height=150&src=pr&token=wb6azJjRSY)](https://codecov.io/gh/postlund/pyatv/pull/1004?src=pr&el=tree)

```diff
@@            Coverage Diff             @@
##           master    #1004      +/-   ##
==========================================
+ Coverage   95.71%   95.98%   +0.27%     
==========================================
  Files          40       40              
  Lines        3755     3840      +85     
==========================================
+ Hits         3594     3686      +92     
+ Misses        161      154       -7     
```

| Flag | Coverage Δ | |
|---|---|---|
| unittests | `95.98% <97.42%> (?)` | |

Flags with carried forward coverage won't be shown. [Click here](https://docs.codecov.io/docs/carryforward-flags#carryforward-flags-in-the-pull-request-comment) to find out more.

| [Impacted Files](https://codecov.io/gh/postlund/pyatv/pull/1004?src=pr&el=tree) | Coverage Δ | |
|---|---|---|
| [pyatv/dmap/tag\_definitions.py](https://codecov.io/gh/postlund/pyatv/pull/1004/diff?src=pr&el=tree#diff-cHlhdHYvZG1hcC90YWdfZGVmaW5pdGlvbnMucHk=) | `88.88% <ø> (ø)` | |
| [pyatv/support/hap\_tlv8.py](https://codecov.io/gh/postlund/pyatv/pull/1004/diff?src=pr&el=tree#diff-cHlhdHYvc3VwcG9ydC9oYXBfdGx2OC5weQ==) | `100.00% <ø> (ø)` | |
| [pyatv/mrp/connection.py](https://codecov.io/gh/postlund/pyatv/pull/1004/diff?src=pr&el=tree#diff-cHlhdHYvbXJwL2Nvbm5lY3Rpb24ucHk=) | `82.47% <71.42%> (+0.36%)` | :arrow_up: |
| [pyatv/support/knock.py](https://codecov.io/gh/postlund/pyatv/pull/1004/diff?src=pr&el=tree#diff-cHlhdHYvc3VwcG9ydC9rbm9jay5weQ==) | `85.18% <75.00%> (-7.92%)` | :arrow_down: |
| [pyatv/support/mdns.py](https://codecov.io/gh/postlund/pyatv/pull/1004/diff?src=pr&el=tree#diff-cHlhdHYvc3VwcG9ydC9tZG5zLnB5) | `88.00% <92.30%> (+0.10%)` | :arrow_up: |
| [pyatv/support/dns.py](https://codecov.io/gh/postlund/pyatv/pull/1004/diff?src=pr&el=tree#diff-cHlhdHYvc3VwcG9ydC9kbnMucHk=) | `95.41% <96.49%> (+1.59%)` | :arrow_up: |
| [pyatv/mrp/player\_state.py](https://codecov.io/gh/postlund/pyatv/pull/1004/diff?src=pr&el=tree#diff-cHlhdHYvbXJwL3BsYXllcl9zdGF0ZS5weQ==) | `99.02% <98.00%> (+0.08%)` | :arrow_up: |
| [pyatv/dmap/\_\_init\_\_.py](https://codecov.io/gh/postlund/pyatv/pull/1004/diff?src=pr&el=tree#diff-cHlhdHYvZG1hcC9fX2luaXRfXy5weQ==) | `97.74% <98.27%> (+0.60%)` | :arrow_up: |
| [pyatv/airplay/pairing.py](https://codecov.io/gh/postlund/pyatv/pull/1004/diff?src=pr&el=tree#diff-cHlhdHYvYWlycGxheS9wYWlyaW5nLnB5) | `100.00% <100.00%> (ø)` | |
| [pyatv/airplay/srp.py](https://codecov.io/gh/postlund/pyatv/pull/1004/diff?src=pr&el=tree#diff-cHlhdHYvYWlycGxheS9zcnAucHk=) | `97.16% <100.00%> (+0.02%)` | :arrow_up: |
| ... and [13 more](https://codecov.io/gh/postlund/pyatv/pull/1004/diff?src=pr&el=tree-more) | |

------

[Continue to review full report at Codecov](https://codecov.io/gh/postlund/pyatv/pull/1004?src=pr&el=continue).
> **Legend** - [Click here to learn more](https://docs.codecov.io/docs/codecov-delta)
> `Δ = absolute <relative> (impact)`, `ø = not affected`, `? = missing data`
> Powered by [Codecov](https://codecov.io/gh/postlund/pyatv/pull/1004?src=pr&el=footer). Last update [ea1f816...225966f](https://codecov.io/gh/postlund/pyatv/pull/1004?src=pr&el=lastupdated). Read the [comment docs](https://docs.codecov.io/docs/pull-request-comments).


Patch:
diff --git a/pyatv/dmap/__init__.py b/pyatv/dmap/__init__.py
index dae57750..9a69e633 100644
--- a/pyatv/dmap/__init__.py
+++ b/pyatv/dmap/__init__.py
@@ -536,6 +536,7 @@ class DmapPushUpdater(PushUpdater):
             # exceptions to keep the API.
             except Exception as ex:  # pylint: disable=broad-except
                 _LOGGER.debug("Playstatus error occurred: %s", ex)
+                self._atv.playstatus_revision = 0
                 self.loop.call_soon(self.listener.playstatus_error, self, ex)
 
         self._future = None


Test patch:
diff --git a/tests/common_functional_tests.py b/tests/common_functional_tests.py
index 23368025..d1359908 100644
--- a/tests/common_functional_tests.py
+++ b/tests/common_functional_tests.py
@@ -77,7 +77,7 @@ class CommonFunctionalTests(AioHTTPTestCase):
                 f"{feature} has wrong state",
             )
 
-    async def waitForButtonPress(self, button: str, action: Optional[InputAction]):
+    async def wait_for_button_press(self, button: str, action: Optional[InputAction]):
         await until(lambda: self.state.last_button_pressed == button)
         await until(lambda: self.state.last_button_action == action)
 
@@ -166,57 +166,57 @@ class CommonFunctionalTests(AioHTTPTestCase):
     @unittest_run_loop
     async def test_button_up(self):
         await self.atv.remote_control.up()
-        await self.waitForButtonPress("up", InputAction.SingleTap)
+        await self.wait_for_button_press("up", InputAction.SingleTap)
 
     @unittest_run_loop
     async def test_button_down(self):
         await self.atv.remote_control.down()
-        await self.waitForButtonPress("down", InputAction.SingleTap)
+        await self.wait_for_button_press("down", InputAction.SingleTap)
 
     @unittest_run_loop
     async def test_button_left(self):
         await self.atv.remote_control.left()
-        await self.waitForButtonPress("left", InputAction.SingleTap)
+        await self.wait_for_button_press("left", InputAction.SingleTap)
 
     @unittest_run_loop
     async def test_button_right(self):
         await self.atv.remote_control.right()
-        await self.waitForButtonPress("right", InputAction.SingleTap)
+        await self.wait_for_button_press("right", InputAction.SingleTap)
 
     @unittest_run_loop
     async def test_button_select(self):
         await self.atv.remote_control.select()
-        await self.waitForButtonPress("select", InputAction.SingleTap)
+        await self.wait_for_button_press("select", InputAction.SingleTap)
 
     @unittest_run_loop
     async def test_button_menu(self):
         await self.atv.remote_control.menu()
-        await self.waitForButtonPress("menu", InputAction.SingleTap)
+        await self.wait_for_button_press("menu", InputAction.SingleTap)
 
     @unittest_run_loop
     async def test_button_play(self):
         await self.atv.remote_control.play()
-        await self.waitForButtonPress("play", None)
+        await self.wait_for_button_press("play", None)
 
     @unittest_run_loop
     async def test_button_pause(self):
         await self.atv.remote_control.pause()
-        await self.waitForButtonPress("pause", None)
+        await self.wait_for_button_press("pause", None)
 
     @unittest_run_loop
     async def test_button_stop(self):
         await self.atv.remote_control.stop()
-        await self.waitForButtonPress("stop", None)
+        await self.wait_for_button_press("stop", None)
 
     @unittest_run_loop
     async def test_button_next(self):
         await self.atv.remote_control.next()
-        await self.waitForButtonPress("nextitem", None)
+        await self.wait_for_button_press("nextitem", None)
 
     @unittest_run_loop
     async def test_button_previous(self):
         await self.atv.remote_control.previous()
-        await self.waitForButtonPress("previtem", None)
+        await self.wait_for_button_press("previtem", None)
 
     @unittest_run_loop
     async def test_button_volume_up(self):
diff --git a/tests/dmap/test_dmap_functional.py b/tests/dmap/test_dmap_functional.py
index a89d9910..16045d9c 100644
--- a/tests/dmap/test_dmap_functional.py
+++ b/tests/dmap/test_dmap_functional.py
@@ -1,6 +1,7 @@
 """Functional tests using the API with a fake DMAP Apple TV."""
 
 import asyncio
+import logging
 import ipaddress
 
 from aiohttp.test_utils import unittest_run_loop
@@ -24,6 +25,8 @@ from tests import zeroconf_stub, common_functional_tests
 from tests.common_functional_tests import DummyDeviceListener
 from tests.utils import until
 
+_LOGGER = logging.getLogger(__name__)
+
 HSGID = "12345678-6789-1111-2222-012345678911"
 PAIRING_GUID = "0x0000000000000001"
 SESSION_ID = 55555
@@ -158,7 +161,7 @@ class DMAPFunctionalTest(common_functional_tests.CommonFunctionalTests):
     @unittest_run_loop
     async def test_button_top_menu(self):
         await self.atv.remote_control.top_menu()
-        await self.waitForButtonPress("topmenu", InputAction.SingleTap)
+        await self.wait_for_button_press("topmenu", InputAction.SingleTap)
 
     @unittest_run_loop
     async def test_button_play_pause(self):
@@ -294,3 +297,38 @@ class DMAPFunctionalTest(common_functional_tests.CommonFunctionalTests):
         await self.atv.remote_control.skip_backward()
         metadata = await self.playing()
         self.assertEqual(metadata.position, prev_position - SKIP_TIME)
+
+    @unittest_run_loop
+    async def test_reset_revision_if_push_updates_fail(self):
+        """Test that revision is reset when an error occurs during push update.
+
+        This test sets up video as playing with revision 0. When the push updater starts,
+        that video is returned to the listener. After that, the next update is fetched
+        with revision 1. Since no media is configured for that revision, an error occurs
+        where new video is configured for revision 0 again (now with "title2" as title),
+        which is fetched and returned to the listener.
+        """
+
+        class PushListener:
+            def __init__(self):
+                self.playing = None
+
+            def playstatus_update(self, updater, playstatus):
+                _LOGGER.debug("Got playstatus: %s", playstatus)
+                self.playing = playstatus
+
+            @staticmethod
+            def playstatus_error(updater, exception):
+                _LOGGER.warning("Got error: %s", exception)
+
+                # Set new content for revision 0 as an error should reset revision
+                self.usecase.example_video(title="video2", revision=0)
+
+        self.usecase.example_video(title="video1", revision=0)
+
+        listener = PushListener()
+        self.atv.push_updater.listener = listener
+        self.atv.push_updater.start()
+
+        await until(lambda: listener.playing and listener.playing.title == "video2")
+        self.assertEqual(listener.playing.title, "video2")
diff --git a/tests/mrp/test_mrp_functional.py b/tests/mrp/test_mrp_functional.py
index c9b3d46a..6e20a9bb 100644
--- a/tests/mrp/test_mrp_functional.py
+++ b/tests/mrp/test_mrp_functional.py
@@ -66,66 +66,66 @@ class MRPFunctionalTest(common_functional_tests.CommonFunctionalTests):
     @unittest_run_loop
     async def test_button_up_actions(self):
         await self.atv.remote_control.up(action=InputAction.DoubleTap)
-        await self.waitForButtonPress("up", InputAction.DoubleTap)
+        await self.wait_for_button_press("up", InputAction.DoubleTap)
 
         await self.atv.remote_control.up(action=InputAction.Hold)
-        await self.waitForButtonPress("up", InputAction.Hold)
+        await self.wait_for_button_press("up", InputAction.Hold)
 
     @unittest_run_loop
     async def test_button_down_actions(self):
         await self.atv.remote_control.down(action=InputAction.DoubleTap)
-        await self.waitForButtonPress("down", InputAction.DoubleTap)
+        await self.wait_for_button_press("down", InputAction.DoubleTap)
 
         await self.atv.remote_control.down(action=InputAction.Hold)
-        await self.waitForButtonPress("down", InputAction.Hold)
+        await self.wait_for_button_press("down", InputAction.Hold)
 
     @unittest_run_loop
     async def test_button_left_actions(self):
         await self.atv.remote_control.left(action=InputAction.DoubleTap)
-        await self.waitForButtonPress("left", InputAction.DoubleTap)
+        await self.wait_for_button_press("left", InputAction.DoubleTap)
 
         await self.atv.remote_control.left(action=InputAction.Hold)
-        await self.waitForButtonPress("left", InputAction.Hold)
+        await self.wait_for_button_press("left", InputAction.Hold)
 
     @unittest_run_loop
     async def test_button_right_actions(self):
         await self.atv.remote_control.right(action=InputAction.DoubleTap)
-        await self.waitForButtonPress("right", InputAction.DoubleTap)
+        await self.wait_for_button_press("right", InputAction.DoubleTap)
 
         await self.atv.remote_control.right(action=InputAction.Hold)
-        await self.waitForButtonPress("right", InputAction.Hold)
+        await self.wait_for_button_press("right", InputAction.Hold)
 
     @unittest_run_loop
     async def test_button_top_menu(self):
         await self.atv.remote_control.top_menu()
-        await self.waitForButtonPress("top_menu", InputAction.SingleTap)
+        await self.wait_for_button_press("top_menu", InputAction.SingleTap)
 
     @unittest_run_loop
     async def test_button_home(self):
         await self.atv.remote_control.home()
-        await self.waitForButtonPress("home", InputAction.SingleTap)
+        await self.wait_for_button_press("home", InputAction.SingleTap)
 
         await self.atv.remote_control.home(action=InputAction.DoubleTap)
-        await self.waitForButtonPress("home", InputAction.DoubleTap)
+        await self.wait_for_button_press("home", InputAction.DoubleTap)
 
         await self.atv.remote_control.home(action=InputAction.Hold)
-        await self.waitForButtonPress("home", InputAction.Hold)
+        await self.wait_for_button_press("home", InputAction.Hold)
 
     @unittest_run_loop
     async def test_button_select_actions(self):
         await self.atv.remote_control.select(action=InputAction.DoubleTap)
-        await self.waitForButtonPress("select", InputAction.DoubleTap)
+        await self.wait_for_button_press("select", InputAction.DoubleTap)
 
         await self.atv.remote_control.select(action=InputAction.Hold)
-        await self.waitForButtonPress("select", InputAction.Hold)
+        await self.wait_for_button_press("select", InputAction.Hold)
 
     @unittest_run_loop
     async def test_button_menu_actions(self):
         await self.atv.remote_control.menu(action=InputAction.DoubleTap)
-        await self.waitForButtonPress("menu", InputAction.DoubleTap)
+        await self.wait_for_button_press("menu", InputAction.DoubleTap)
 
         await self.atv.remote_control.menu(action=InputAction.Hold)
-        await self.waitForButtonPress("menu", InputAction.Hold)
+        await self.wait_for_button_press("menu", InputAction.Hold)
 
     @unittest_run_loop
     async def test_button_suspend(self):