[Session] たまに意図しないタイミングでINTERRUPTが返ってくる

[p1ass]

概要

たまに意図しないタイミングでINTERRUPTが返ってくる。

再現方法

再現ではないが、ログから想像される動作

1. PUT /sessions/:id/stateでPLAYを叩く
2. PLAY イベントが飛ぶ
3. start trackend trigger
4. create timer
5. currentOperation Play
6. start timer remainDuration : 58.816s ←これがおかしい 本来1分半の曲
7. trigger expired
8. next track
9. playing different track
10. INTERRUPT

ログ

{"time":"2020-08-05T12:11:56.002525926Z","id":"","remote_ip":"175.131.95.104","host":"relaym-server-dev.camph.net","method":"OPTIONS","uri":"/api/v3/sessions/e24191d8-9d62-4122-941c-38cf2b4cb3d3/state","user_agent":"Mozilla/5.0 (iPhone; CPU iPhone OS 13_5 like Mac OS X) AppleWebKit/605.1.15 (KHTML, like Gecko) CriOS/84.0.4147.71 Mobile/15E148 Safari/604.1","status":204,"error":"","latency":43499,"latency_human":"43.499µs","bytes_in":0,"bytes_out":0}
{"time":"2020-08-05T12:11:56.109195363Z","level":"DEBUG","prefix":"application","file":"session.go","line":"167","message":"playORResume sessionID=e24191d8-9d62-4122-941c-38cf2b4cb3d3: call set repeat off api: spotify api: set repeat mode: Player command failed: No active device found: active device not found"}
{"time":"2020-08-05T12:11:56.109264065Z","id":"","remote_ip":"xxx.xxx.xx.xxx","host":"relaym-server-dev.camph.net","method":"PUT","uri":"/api/v3/sessions/e24191d8-9d62-4122-941c-38cf2b4cb3d3/state","user_agent":"Mozilla/5.0 (iPhone; CPU iPhone OS 13_5 like Mac OS X) AppleWebKit/605.1.15 (KHTML, like Gecko) CriOS/84.0.4147.71 Mobile/15E148 Safari/604.1","status":403,"error":"code=403, message=active device not found","latency":69566512,"latency_human":"69.566512ms","bytes_in":16,"bytes_out":38}
{"time":"2020-08-05T12:11:59.109584215Z","id":"","remote_ip":"xxx.xxx.xx.xxx","host":"relaym-server-dev.camph.net","method":"OPTIONS","uri":"/api/v3/sessions/e24191d8-9d62-4122-941c-38cf2b4cb3d3","user_agent":"Mozilla/5.0 (iPhone; CPU iPhone OS 13_5 like Mac OS X) AppleWebKit/605.1.15 (KHTML, like Gecko) CriOS/84.0.4147.71 Mobile/15E148 Safari/604.1","status":204,"error":"","latency":41531,"latency_human":"41.531µs","bytes_in":0,"bytes_out":0}
{"time":"2020-08-05T12:11:59.261297897Z","id":"","remote_ip":"xxx.xxx.xx.xxx","host":"relaym-server-dev.camph.net","method":"GET","uri":"/api/v3/sessions/e24191d8-9d62-4122-941c-38cf2b4cb3d3","user_agent":"Mozilla/5.0 (iPhone; CPU iPhone OS 13_5 like Mac OS X) AppleWebKit/605.1.15 (KHTML, like Gecko) CriOS/84.0.4147.71 Mobile/15E148 Safari/604.1","status":200,"error":"","latency":114000402,"latency_human":"114.000402ms","bytes_in":0,"bytes_out":6358}
{"time":"2020-08-05T12:12:01.322654242Z","level":"DEBUG","prefix":"application","file":"hub.go","line":"52","event":{"type":"PLAY"},"message":"push message","sessionID":"e24191d8-9d62-4122-941c-38cf2b4cb3d3"}
{"time":"2020-08-05T12:12:01.322692319Z","id":"","remote_ip":"xxx.xxx.xx.xxx","host":"relaym-server-dev.camph.net","method":"PUT","uri":"/api/v3/sessions/e24191d8-9d62-4122-941c-38cf2b4cb3d3/state","user_agent":"Mozilla/5.0 (iPhone; CPU iPhone OS 13_5 like Mac OS X) AppleWebKit/605.1.15 (KHTML, like Gecko) CriOS/84.0.4147.71 Mobile/15E148 Safari/604.1","status":202,"error":"","latency":2213172515,"latency_human":"2.213172515s","bytes_in":16,"bytes_out":0}
{"time":"2020-08-05T12:12:01.322840868Z","level":"DEBUG","prefix":"application","file":"session_timer.go","line":"33","message":"start track end trigger","sessionID":"e24191d8-9d62-4122-941c-38cf2b4cb3d3"}
{"time":"2020-08-05T12:12:01.322861752Z","level":"DEBUG","prefix":"application","file":"sync_check_timer.go","line":"88","message":"create timer","sessionID":"e24191d8-9d62-4122-941c-38cf2b4cb3d3"}
{"time":"2020-08-05T12:12:01.362689231Z","id":"","remote_ip":"xxx.xxx.xx.xxx","host":"relaym-server-dev.camph.net","method":"OPTIONS","uri":"/api/v3/sessions/e24191d8-9d62-4122-941c-38cf2b4cb3d3","user_agent":"Mozilla/5.0 (Macintosh; Intel Mac OS X 10_14_6) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/84.0.4147.105 Safari/537.36","status":204,"error":"","latency":46729,"latency_human":"46.729µs","bytes_in":0,"bytes_out":0}
{"time":"2020-08-05T12:12:01.445557054Z","id":"","remote_ip":"xxx.xxx.xx.xxx","host":"relaym-server-dev.camph.net","method":"GET","uri":"/api/v3/sessions/e24191d8-9d62-4122-941c-38cf2b4cb3d3","user_agent":"Mozilla/5.0 (iPhone; CPU iPhone OS 13_5 like Mac OS X) AppleWebKit/605.1.15 (KHTML, like Gecko) CriOS/84.0.4147.71 Mobile/15E148 Safari/604.1","status":200,"error":"","latency":77931412,"latency_human":"77.931412ms","bytes_in":0,"bytes_out":6404}
{"time":"2020-08-05T12:12:01.523265594Z","id":"","remote_ip":"xxx.xxx.xx.xxx","host":"relaym-server-dev.camph.net","method":"GET","uri":"/api/v3/sessions/e24191d8-9d62-4122-941c-38cf2b4cb3d3","user_agent":"Mozilla/5.0 (Linux; Android 6.0.1; Moto G (4)) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/84.0.4147.105 Mobile Safari/537.36","status":200,"error":"","latency":117360184,"latency_human":"117.360184ms","bytes_in":0,"bytes_out":6404}
{"time":"2020-08-05T12:12:06.435531289Z","level":"DEBUG","prefix":"application","file":"session_timer.go","line":"130","currentOperation":"play","message":"currentOperation"}
{"time":"2020-08-05T12:12:06.435560141Z","level":"INFO","prefix":"application","file":"session_timer.go","line":"144","message":"start timer","remainDuration":"58.816s","sessionID":"e24191d8-9d62-4122-941c-38cf2b4cb3d3"}
{"time":"2020-08-05T12:12:41.439074844Z","level":"DEBUG","prefix":"application","file":"hub.go","line":"89","message":"unregister websocket","sessionID":"e24191d8-9d62-4122-941c-38cf2b4cb3d3"}
{"time":"2020-08-05T12:13:05.255034147Z","level":"DEBUG","prefix":"application","file":"session_timer.go","line":"74","message":"trigger expired","sessionID":"e24191d8-9d62-4122-941c-38cf2b4cb3d3"}
{"time":"2020-08-05T12:13:05.256699647Z","level":"DEBUG","prefix":"application","file":"session_timer.go","line":"223","message":"next track","queueHead":8,"sessionID":"e24191d8-9d62-4122-941c-38cf2b4cb3d3"}
{"time":"2020-08-05T12:13:06.762683429Z","id":"","remote_ip":"xxx.xxx.xx.xxx","host":"relaym-server-dev.camph.net","method":"OPTIONS","uri":"/api/v3/sessions/e24191d8-9d62-4122-941c-38cf2b4cb3d3","user_agent":"Mozilla/5.0 (Macintosh; Intel Mac OS X 10_14_6) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/84.0.4147.105 Safari/537.36","status":204,"error":"","latency":43707,"latency_human":"43.707µs","bytes_in":0,"bytes_out":0}
{"time":"2020-08-05T12:13:06.991350866Z","id":"","remote_ip":"xxx.xxx.xx.xxx","host":"relaym-server-dev.camph.net","method":"GET","uri":"/api/v3/sessions/e24191d8-9d62-4122-941c-38cf2b4cb3d3","user_agent":"Mozilla/5.0 (Linux; Android 6.0.1; Moto G (4)) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/84.0.4147.105 Mobile Safari/537.36","status":200,"error":"","latency":116993265,"latency_human":"116.993265ms","bytes_in":0,"bytes_out":6406}
{"time":"2020-08-05T12:13:12.37278278Z","level":"INFO","prefix":"application","file":"session.go","line":"126","message":"session playing different track","playingTrack":{"URI":"spotify:track:1Hu32l2RyeyLAhPLROoa4V","ID":"1Hu32l2RyeyLAhPLROoa4V","Name":"銀の音さやか","Duration":94185000000,"Artists":[{"Name":"柳川和樹"}],"URL":"https://open.spotify.com/track/1Hu32l2RyeyLAhPLROoa4V","Album":{"Name":"ライザのアトリエ 〜常闇の女王と秘密の隠れ家〜 オリジナルサウンドトラック","Images":[{"URL":"https://i.scdn.co/image/ab67616d0000b2738c066473a7d92e0d7159b355","Height":640,"Width":640},{"URL":"https://i.scdn.co/image/ab67616d00001e028c066473a7d92e0d7159b355","Height":300,"Width":300},{"URL":"https://i.scdn.co/image/ab67616d000048518c066473a7d92e0d7159b355","Height":64,"Width":64}]}},"queueTrack":"spotify:track:68PL1tscUpqoMBMHMKqwUh"}
{"time":"2020-08-05T12:13:12.372846181Z","level":"DEBUG","prefix":"application","file":"session_timer.go","line":"242","message":"interrupt detected","sessionID":"e24191d8-9d62-4122-941c-38cf2b4cb3d3"}
{"time":"2020-08-05T12:13:12.372870552Z","level":"DEBUG","prefix":"application","file":"hub.go","line":"52","event":{"type":"INTERRUPT"},"message":"push message","sessionID":"e24191d8-9d62-4122-941c-38cf2b4cb3d3"}

対処方法

• Task1

[p1ass]

INTERRUPTした後に再生しようとするとおかしいCurrentlyPlayingInfoが返ってくる気がする

[p1ass]

再現できた気がする

1. 適当な曲を2曲追加する
2. 1曲目再生中に別のアプリで音楽を再生しはじめることで、Spotifyアプリの再生をやめる
3. サーバのログでINTERRUPTが出るまで、Relaymを開かないようにする (具体的にはGetSessionを叩かれないようにする)
4. INTERRUPTが出たらスマホでRelaymの再生ボタンを押して再生動作を始めると、1曲目の再生を辞めた時間からのタイマーがセットされ、0秒からスタートしない

[p1ass]

完璧に理解した
（修正はまだ）

[p1ass]

これSpotifyのAPIが返すCurrentlyPlayingのProgressの更新が遅いのが駄目っぽい

[p1ass]

これSpotify APIのバグでは！？！？

[p1ass]

↑の再現手順を踏むと、Spotifyアプリの再生時間とAPIのProgressの秒数が違う状態で返ってくるようになる。
再生中の曲名はあってる

しかも面白いのが、再生中は間違った秒数を返してくるんだけど、一時停止中は正しい秒数を返してくる。

Relaymで「再生→一時停止→再生」としたときに、返ってくる秒数は「間違ってる→正しい→間違ってる」 という感じになる

これの解決方法はSoptifyアプリで再生バーをいじることだけ

[sanposhiho]

‪Spotify API( ･᷄д･᷅ )‬

[p1ass]

ずっと試してたら再現しなくなった、、、

[sanposhiho]

おりょ…明日か土日か辺りに僕も試して見ますね

[p1ass]

もしやSpotifyが直してくれた！？（んなわけ）

[p1ass]

もしかして再生開始時にProgressを0としてAPIコールすれば解決する説(シークバーで直ることを考えると)

[sanposhiho]

試す価値ありそう