Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

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

Open
1 task
p1ass opened this issue Aug 5, 2020 · 12 comments
Open
1 task

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

p1ass opened this issue Aug 5, 2020 · 12 comments
Assignees
@p1ass
Labels
bug Something isn't working

Comments

@p1ass
Copy link
Member

p1ass commented Aug 5, 2020 •
edited
Loading

概要

たまに意図しないタイミングで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 p1ass added the bug Something isn't working label Aug 5, 2020
@p1ass p1ass self-assigned this Aug 5, 2020
@p1ass
Copy link
Member Author

p1ass commented Aug 5, 2020

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

@p1ass p1ass mentioned this issue Aug 5, 2020
Merged
@p1ass
Copy link
Member Author

p1ass commented Aug 5, 2020 •
edited
Loading

再現できた気がする

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

@p1ass
Copy link
Member Author

p1ass commented Aug 5, 2020

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

@p1ass
Copy link
Member Author

p1ass commented Aug 6, 2020

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

@p1ass
Copy link
Member Author

p1ass commented Aug 6, 2020

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

@p1ass
Copy link
Member Author

p1ass commented Aug 6, 2020 •
edited
Loading

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

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

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

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

@sanposhiho
Copy link
Member

‪Spotify API( ･᷄д･᷅ )‬

@p1ass
Copy link
Member Author

p1ass commented Aug 6, 2020

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

@sanposhiho
Copy link
Member

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

@p1ass
Copy link
Member Author

p1ass commented Aug 6, 2020

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

@p1ass
Copy link
Member Author

p1ass commented Aug 6, 2020

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

@sanposhiho
Copy link
Member

試す価値ありそう

@p1ass p1ass mentioned this issue Aug 6, 2020
Merged
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@p1ass p1ass

Labels
bug Something isn't working
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@p1ass @sanposhiho