DSAS開発者の部屋

学習型の赤外線リモコンを使っているとたまにうまく反応しない機器に遭遇することがあります。信号の学習を慎重に行うのは当然として、別の学習リモコン製品では問題のみられないケースもあるためこうした場合にはしばしば「相性」という曖昧な表現が用いられます。しかし、そこには必ず具体的な原因があるはずです。最近の活動の一環として、情報のほとんど見当たらないこの件について調べてみることにしました。

きっかけ

自宅で株式会社ピクセラ様による下記の TV チューナを使っています。

• PRODIA（プロディア） : 地上デジタルチューナー「PRD-BT105-P00」 - www.pixela.co.jp
  • PIXELA地上デジタルチューナーPRD-BT107-P00 - www.amazon.co.jp
    

コンパクトでありながら基本性能がとてもしっかりしていることが気に入りプライベートで愛用している製品です。ただ、このチューナは付属のリモコンには機敏に反応するものの、自宅で長年いろいろな機器の操作に使っている手持ち式の某学習リモコンの信号にはほとんど反応しないことを不思議に思っていました。今から 1 年ほど前に導入したあるメジャーなスマートリモコン製品からの操作においても同じ状況だったのですが、すでに純正リモコンでの操作に馴染んでいたこともありあまり気にかけずにいました。

その話題とは無関係に先日高齢の身内のためにできるだけシンプルな学習リモコンが必要になり国外のマーケットから写真の 6 ボタンのみの安価な学習リモコンを調達しました。メーカーは不明、多少割高ながら Amazon.co.jp のマーケットプレイスにも出品されているようです。

このスティック型のリモコンの動作確認を行う過程でふと上のチューナを試してみたところ、これまでの経験が嘘のようにあっさりと反応しました。この結果に驚き、たまたま最近赤外線通信の勉強がてらに ESP32 ボードを使って試作中だった学習リモコン（※）で試してみるとその結果も OK でした。

（※）この試作は所定のリモコン信号をサンプリングした結果をそのまま信号の再現に利用する素朴な内容のものです

この違いは一体何によるものなのか？ にわかに興味が湧いてきました。今回はこの件について調べた内容とその結果を紹介します。手元ではこういった視点で事情を掘り下げた例をまだ目にしたことがありませんが、興味深い結果が得られました。

1. 道具立て

なお、ごのチューナのリモコン信号の形式は家製協フォーマットだった。

2. 信号全体の波形を評価する

この結果から、手元のチューナに A, B の信号が受けいれられ、C, D の信号が弾かれる現象の主因は信号全体のタイミングのずれではないことが推察される。

3. 信号を構成するパルスの品質を評価する

元信号との波形全体の照合でのタイミングずれは目立たなかったが、パルス幅にもパルス比にも非常にばらつきが大きい。はた目には多くの機器がこの製品の信号でコントロールできていることのほうが不思議にさえ感じられる。一般の家電製品においてリモコン信号データ解釈の許容範囲が広く設定されていることが察せられる。広く利用されている製品であるにもかかわらずこれほど乱れた信号を出しているとは想像していなかった。手元の個体固有の問題？ ロットによる品質のばらつき？ あるいはスマートリモコンの性質上複数の赤外線 LED を搭載していることの何らかの影響か？ いずれにせよ、前掲の「手持ち型リモコン C」の信号を受けいれない機器にこの信号が通用するとは考えにくい。

4. 結論

前項に掲げたパルス幅・パルス比のヒストグラムの図をあらためて並べてみる。俯瞰すると「手持ち型リモコン C」「スマートリモコン D」の信号に含まれるパルス群の品質の乱調がはっきりと見てとれる。他のリモコン分の特徴との差違が顕著であることから、このふたつの学習リモコンの信号が手元のチューナに受けいれられない現象の主因はこのパルスの粒度の乱れにあるものと想定される。

所感

今回の調査を通じて、おそらくは赤外線リモコンの信号に限らずパルス信号全般に共通する品質評価軸の一端を学ぶことができたように思います。目視では波形の全体像が元のリモコン信号のそれとよく似ているにもかかわらず、スマートリモコン D による再現信号（以下に元信号波形との照合図を再掲）が実在の機器で弾かれるケースのあることは象徴的です。

オシロスコープ等で巨視的に信号波形全体を観察することには便宜があり、またその確認はこういった調査を行う際には欠かせませんが、無線通信に用いられる信号はあくまでも先頭から順を追って内容を汲んでいくものであり時間の概念を含まないバーコードのように視覚を通じ一瞬で全体をとらえそこから情報を採取していく性質のものではありません。そのため、信号の品質を判断するためには時間軸にそってミクロに解釈を行う必要もあることを認識する良い機会となりました。

自分の自由を拘束してみることの価値

生活をより便利にするための製品やサービスの開発と普及が加速しています。新しいものは大いに活用したいところですが、一方で利便性への過剰な没入はしばしば怠惰・依存・不健康といった負の要素と背中合わせであることにも注意しておきたいものです。
近年、スマートホーム等のキーワードに象徴される光景とは逆向きにあえて利用者に不便を強いるための機器が出始めていることを知り関心を持ちました。
不自由さのあとの自由からはその恩恵をあらためて新鮮な思いで学ぶことができるでしょう。あるいは、今まで自分にとって重要で欠かせないと思っていたものとの関係を見直すきっかけとなるかもしれません。そのように、普段あまりに見なれた自由との間に距離をおいてみる試みは、自分の日常への向き合い方を考えるための材料のひとつになりえるのではないでしょうか。

• ずいぶん昔に読んだ、故・中島らもさんのエッセイを思い出しました。要旨のみを本文から引用します
  中島 らも （著） 「とほほのほ」 1991/1 - www.amazon.co.jp
  「楽園はどこにあるのか （4）」 より
  

  そのマヤの「現世-楽園置換装置」というのは、かなり大きなドームの形をしている。内部はガランとした空洞で、この遺跡からは多量の炭化した「トウガラシ」が発見された。神官たちは支配下の善男善女たちをこのドームに入れ、大量のトウガラシをいぶした煙をドーム内にあおぎ入れたのだろう。人々は恐怖と苦痛で、発狂と死の直前まで追い込まれる。そのときドームの戸が開かれる。冷たくて香りのよい空気がなだれ込んでくる。人々は自分が立っている「いま」「ここ」がすなわち楽園にほかならないことを確信するのだ。

製品の例

1. kSafe

概要

kSafe は Kitchen Safe Inc （米 カリフォルニア）による製品。 タイマーつきの電子ロック式小物入れ。あらかじめ設定した時間が経過しなければ中身を取り出せないしくみで、日常生活において依存対象となりがちなスマートフォンやもろもろの嗜好品へ接触する自由を自分自身で制限することができる。
以下、公式サイトの記事より。

• kSafe by Kitchen Safe | The Time Lock Safe - www.thekitchensafe.com
  

  
  
  A powerful tool
  to build good habits
  
  Once the timer is set, and the button is pressed, the safe will remain locked until the timer reaches zero.
  No overrides!

  
  www.thekitchensafe.com
  
• frequently asked questions | kSafe by Kitchen Safe - www.thekitchensafe.com
  

  Why do I need the kSafe?
  
  Short Answer - Because it’s really cool! And, it’s been scientifically proven to increase your chances of reaching your goals.
  
  Long Answer - The kSafe was developed based on research published by scientists at MIT, Harvard, Stanford, Princeton, and Yale. They discovered that pre-commitment can significantly increase our chances of achieving our goals.   :

  Google 訳

  なぜkSafeが必要なのですか？
  
  簡単な回答 - 本当にクールだから！ そして、あなたの目標を達成する可能性を高めることが科学的に証明されています。
  
  長い答え - kSafeは、MIT、ハーバード、スタンフォード、プリンストン、エールの科学者によって発表された研究に基づいて開発されました。 彼らは、事前コミットメントが私達の目標を達成する私達の可能性をかなり高めることができることを発見した。   :

権威めいたものを引き合いに出しながら肝心の「いつ・どこで・誰が・どのように」が省略されていることが残念だが、製品そのものは興味ぶかい。

価格

ただし、この kSafe は結構値が張る。下記のように公式サイトからの直販でノーマルサイズの「Medium」が送料別 49米ドルという価格。

• Purchase | kSafe by Kitchen Safe - www.thekitchensafe.com （2019年2月時点）
  
  • Medium - $49
  • Mini - $49
  • XL - $59
    
  www.thekitchensafe.com

逡巡とその後

この製品のコンセプトに関心がからまりしばらく直販サイトを徘徊した。 総額で $49 なら買ってもいいと思ったが、日本への最安送料 $29.34 が加わると Medium で計 $78.34。手元での費用対効果を想定するとこれはかなり微妙で悩ましい金額だった。

上のスクリーンショットのようにカートに入れたまましばらく好奇心と理性の間を行き来していると何日か後に販売元から以下のメールが届いた。 個人的にはこの内容に微妙な印象が残り結局買うのをやめた。

From: kSafe by Kitchen Safe
Date: 2019年2月15日(金) 4:40
Subject: Are you OK? Kitchen Safe is worried
To: xxxxxxxxx@gmail.com

Hey,

We noticed that you didn't complete your Kitchen Safe order! The only reasonable explanation we can think of is that your computer exploded right before you could click "Complete my Order". Don't worry, we saved your shopping cart so you can complete the order from a friend's computer or phone (see bottom of email).

If your computer didn't explode and you're just on the fence, be sure to read some of our customer reviews.

Also, you can apply this coupon: CommitToChange to save 10% on checkout. It expires in the next 24 hours.

Thank you,

The Kitchen Safe Team
www.thekitchensafe.com

今となっては高額出費を抑えられたことにむしろ感謝している。

2. Timer Lock

概要

Timer Lock はノーブランドの中国製品。 名前のとおり上の kSafe と同様のタイマーロック製品であり、こちらは箱型ではなく錠前のスタイル。

www.amazon.co.jp

価格

価格は kSafe に比べれば安い。アマゾンジャパンでは 2000円ほどの価格から販売されている。複数のセラーが存在。

• タイマー式南京錠 USB充電 安心 防犯グッズ - www.amazon.co.jp ￥ 2,099 （2019年2月時点）

購入

買ってみることにした。当初は eBay の利用を考えたが、アマゾンのレビュー等を参照すると製品の大元の品質に対する一抹の懸念が残った。結局、価格差を保険料と割り切り、実際に問題に直面した場合に返品のしやすいアマゾンで購入した。

観察

以下、現物を手にした状態でのメモ。

• サイズ感は写真のとおり
• ワイヤを右側のホールへ装着して使う。差し込んだワイヤは本体右脇のボタン押下でリリース
• 左右ボタンでキッチンタイマー風に時分を設定（最長99時間99秒）し、中央ボタンで開始。5秒間の猶予後はタイマー満了まで解除不可となる
• 錠前の形状ではあるがこういう華奢なつくりなので非常時（？）には簡単に壊すことができる。言いかえれば防犯用途にはまったく適さない
• 内蔵バッテリーを付属の USB ケーブルで充電して使う。本体装着側が MicroB ではなくレアな外径 2.35mm / 内径0.7mm プラグなのがちょっと残念
• 手元では一度のフルチャージを経てこの 2か月ほど週に 3, 4 回、それぞれ 12時間程度のタイマー設定で使っているがまだ充電切れの予兆なし

使用例

自宅の観音開きの押入れをロック対象とすることにした。これなら小物入れ式の kSafe とは異なり楽器など大きなものでも最長 99時間99分後の未来へ預けることができる。 本体のワイヤは押入れの取手を直接ホールドできる長さではないため以前ホームセンターで買った硬質プラスティック素材のチェーンを併用した。写真のようにちょっと物々しい感じに。

動作の様子： 1分17秒　音量注意

所感

実際に使ってみるとこれは望外に良い製品だった。普通に丁寧に扱えば何の問題もない。予備をかねて eBay でもう一台購入。 説明書をみたところではこちらがより新しいバージョンらしい。少しデザインが異なるが機能は同じ。

この価格で買える不自由・非日常の価値は大きい。

付記

手元の一連のメモを上の記事にまとめていたところ、前掲の kSafe のアマゾンジャパンでの販売価格が高騰していることに気がつきました。 アマゾンでは以前からメーカー直販よりもかなり割高な 9,700円という価格で販売されていましたが、現在は 1万円を優に超えておりちょっと驚きました。

• Kitchen Safe タイムロッキングコンテナ (ホワイトクリア) - www.amazon.co.jp
  ￥15,792 （2019年4月29日時点）

元々あまり目立つ製品ではないためかこれまでの観察の範囲ではアマゾンでの価格に変動はありませんでした。不思議に思って情報を探してみると @ryogomatsumaru さんによる 4月22日の次のツイートがこのブームの発端らしいことを知りました。

最近スマホをついつい触りすぎて時間を浪費してることに危機感を覚えて、「設定した時間の間は絶対にあけられない箱」を買ったんだけど、これ思ったよりもずっと仕事がはかどるようになるのでオススメです。

勉強中に携帯いじっちゃう人とか、仕事中に誘惑に負けやすい人。ぜひ。 pic.twitter.com/YBXW6ovpD8

— 松丸 亮吾＠東大ナゾトレ9巻発売中！ (@ryogomatsumaru) 2019年4月22日

すごい影響力ですね。まさに情報の時代であることをあらためて実感しました。話題が重なるのでこの記事はキャンセルしようかとも思いましたが、せっかくなので史上初の10連休と平成最後の日の記念（？）をかねて。

スマートスピーカーの普及に伴いスマートホーム系製品の低価格化が少しずつ進んでいます。 最近プライベートで次の製品を買いました。今のところ安定動作しており自宅で使っている Google Home Mini との相性もよく気に入っています。

• Smart WiFi Plug Mini (MSS110) - MEROSS PRODUCT - www.meross.com
  • 工事設計認証番号: 203-JN0810
  • 公式アプリ: Android 版, iOS 版
    
  • Google Home, Amazon Echo 対応
    
  • IFTTT に専用サービスチャネルあり
• 外観
  
• 動作の様子
  1) 公式アプリ 2) Google Home Mini 3) マイコンボード により照明を操作
  （注：この動画には "OK Google" の発声が含まれます。
  近くに Goole Home デバイスのある場合にはご注意下さい）
  
  
• 公式ストア
  • Meross 認定ショップ - Amazon.co.jp
    • Meross WIFIスマートプラグ 2 個入り ￥3,299 （2019年1月末時点）
    • 単品 ￥ 1,899 （2019年1月末時点）
  • meross Official Store - AliExpress
    • Smart WiFi Plug Mini, 2 Pack Meross MSS110 US $21.99 Free Shipping （日本式プラグ: 2019年1月末時点）
    • 単品 - US $11.99 Free Shipping （日本式プラグ: 2019年1月末時点）

※スマートプラグを使えば家庭用電源から所定の機器への給電を手軽に操作できるため便利ですが、個人的には何らかの原因で自分の意図しない動作が起こった場合に深刻な事態につながりかねない機器との併用は避けています。たとえば少なくとも現時点で電気ストーブなどをつなぐ勇気はありません ^^;

スマートプラグを PC の起動に利用する

スマートスピーカーへの音声指示で PC を起動するアイディアには実用性があり、ネットを検索すると参考になる多くの興味深い例に触れることができます。一方で、Meross Smart Plug Mini を触っているうちにこれを使えばとてもシンプルな道具立てで同様のことを実現できるのではないかと考えました。以下の発想によるものです。

1. このプラグはもともとルータ越しの動作を前提とするクラウドベースのスマートホーム系製品である
2. そのため自前で通信まわりを取り回すことなく所定の機器への給電を屋内外から指示することができる
3. ということは、上記 2. の給電対象の機器を「起動すると LAN 上に所定のマジックパケットを送り出す内容のプログラムを書き込んだマイコンボード」としておけば、スマートスピーカー経由であれ、その他の方法であれ、給電指示ひとつで簡単に LAN 上の所定の PC を起動できるはず

電源投入からのスタートなのでボード側の初期処理に多少の時間がかかることは予想されるものの全体として筋は通っています。特に難しい要素もないため国内外のどこかにすでに同一の事例があるのではないかと想像しましたが、手元でざっと見渡した範囲では見当たらないようです。そんなわけで、まあもし先例があってもいいか、と思いながらざっくり形にしてみることにしました。

実装と動作の様子

スマートプラグからの給電先は何かと融通のきく ESP32 ボードとしました。AC アダプタと USB ケーブルごしにボード単体をプラグへ接続して使います。 プログラムは以下の内容としました。対象 PC が起動すれば当該ボードはお役御免につきプログラムから給電元のプラグをオフにすることで自らをシャットダウンします。

1. 初期処理として WiFi AP との接続を確立
2. 所定のマジックパケットを LAN へ送出
3. マジックパケット送出後に対象 PC へ ping を継続的に発行
4. ping への応答を検知したら自ボードへ給電中のスマートプラグの通電をオフにする

あわせてネットワーク接続時と電源切断前にメールでその旨を通知します。この通知はリモートで操作を行う場合には状況把握のために有用ですが、スマートスピーカーへ声をかけている在宅時にはいささか冗長なのでいずれ手を加えるかもしれません。

ソースコード

Arduino IDE + Arduino core for the ESP32 環境向けに用意したプログラムです。
前項に挙げたメール通知処理には SendGrid を、プラグのシャットダウンには IFTTT アプレットを利用しています。 これらは ESP32_WakeOnLan.h 冒頭の「#define USE_MAIL_NOTIFICATION」「#define USE_AUTO_SHUTDOWN」の定義を無効化すれば省略されます。

• github.com/mkttanabe/ESP32_WakeOnLan
  • ESP32_WakeOnLan.h
  • ESP32_WakeOnLan.ino
• pbecchi 様による github.com/pbecchi/ESP32_ping ライブラリを使用させて頂いています
  • ping.h
  • ping.cpp

デモ

一式の動作の様子を収めた動画です。 （1分10秒）

（注：この動画には "OK Google" の発声が含まれます。
近くに Goole Home デバイスのある場合にはご注意下さい）

余談ながら、手元では過去に何度か Wake On Wan の試みを行いそれぞれ当ブログの記事として公開しています。見返してみると道具立てに微妙に当時の状況が反映されておりちょっと面白く感じました。

• GCM で Wake On WAN （2013年）
• ESP8266 モジュール + Blynk でさらりと Wake On Wan （2015年）

時代が加速を続けています。数年後の未来が楽しみです。

MySQL 5.6 で新たな認証方式 sha256_password が追加され、 MySQL 8 ではその改良版となる caching_sha2_password が追加されました。詳しくは MySQL 8.0.4 : New Default Authentication Plugin : caching_sha2_password を参照してください。

これらは従来の native_password 方式よりも安全とされています。 3つの認証方式について特徴をまとめてみます。

攻撃経路

認証方式を考えるとき、ざっくりと2つの攻撃経路があります。

1つ目は mysql.user テーブルの authentication_string カラム (旧 password カラム) です。このカラムをSELECTできるユーザーが、他のユーザーの authentication_string を閲覧し、その情報を元になりすましができる可能性があります。

2つ目は通信経路です。具体的には盗聴したりサーバーになりすますことで、認証に必要な情報を取得する可能性があります。

3つの認証方式の詳細

caching_sha2_password は sha256_password の改良版です。特に初回の認証は sha256_password と同じです。なのでまずは native_password と sha256_password を比較してみましょう。

native_password

authentication_string カラムの内容は、 native_password が salt なしの純粋な SHA1(SHA1(password)) の先頭に、 MySQL 4.1 以前の形式と区別するための目印として "*" をつけたものです。

mysql> create user t3 identified with 'mysql_native_password' by 'password';
Query OK, 0 rows affected (0.20 sec)

mysql> select Host,User,plugin,authentication_string from mysql.user WHERE User='t3';
+------+------+-----------------------+-------------------------------------------+
| Host | User | plugin                | authentication_string                     |
+------+------+-----------------------+-------------------------------------------+
| %    | t3   | mysql_native_password | *2470C0C06DEE42FD1618BB99005ADCA2EC9D1E19 |
+------+------+-----------------------+-------------------------------------------+
1 row in set (0.00 sec)

mysql> select SHA1(unhex(SHA1('password')));
+------------------------------------------+
| SHA1(unhex(SHA1('password')))            |
+------------------------------------------+
| 2470c0c06dee42fd1618bb99005adca2ec9d1e19 |
+------------------------------------------+
1 row in set (0.00 sec)

このため、複数のユーザーが同じパスワードを利用していると authentication_string も同じになります。また、 NIST により認証に SHA-1 を使うのをやめるように推奨されています。これが前述の記事で説明された、新認証方式が必要になった理由 (native_password の弱点) です。

Client-Serverプロトコル (以降プロトコルと呼ぶ) では、まずサーバーからクライアントに nonce が送られ、クライアントは次の計算結果をサーバーに返します。 (https://dev.mysql.com/doc/internals/en/secure-password-authentication.html#packet-Authentication::Native41 より引用)

SHA1( password ) XOR SHA1( "20-bytes random data from server" <concat> SHA1( SHA1( password ) ) )

サーバーは最初に送信した nonce と SHA1(SHA1(password)) を知っているので、再度 XOR を取ることで SHA1(password) を知ることができます。それにもう一度 SHA1() をかけて authentication_string と一致するかで認証することができます。

攻撃者がこの通信を盗聴した場合、 password や SHA1(password) を知ることができません。

また、 攻撃者がサーバーになりすました場合も、password や SHA1(password)　を知ることができません。ただしリレー攻撃で本物のサーバーに接続することは可能です。

もちろん、攻撃者が authentication_string を知っている場合は、サーバーと同じ手順で SHA1(password) を得ることができます。生のパスワードがなくても SHA1(password) があれば本物のサーバーに対して認証を通ることができます。

sha256_password

authentication_string はSALT付きで SHA256 を複数ラウンドしたものらしいです。実際、同じパスワードのユーザーを複数作成してみても、全員が異なる authentication_string が異なります。攻撃者が同じMySQLサーバーにログインして mysql.user テーブルを閲覧可能な場合は、 native_password よりも格段に安全です。

一方で、認証プロトコルは次のようになっています。

• 安全な経路 (SSL あるいは unix domain socket) では password + nonce を送る。
• それ以外の経路では password を RSA で暗号化して送る。

どちらも適切に設定されている場合は native_password と同等以上に安全だと思います。

ただしサーバーになりすまされた場合に攻撃者に生の password を与えてしまう点は気になります。なりすましを許した時点でリレー攻撃により本物のサーバーに接続して SET PASSWORD を含む任意のクエリを実行されてしまう可能性があるのであくまでも気持ちの問題ですが。

caching_sha2_password

1度目の認証は sha256_password と同じですが、サーバーはそのときに SHA256(password) をキャッシュします。

2度めからの認証は native_password に似た（ただし SHA-256 を利用した）チャレンジ＆レスポンス認証になるので、生パスワードがプロトコル上に乗ることもありませんし、SSLを使っていない環境でRSA暗号化するオーバーヘッドが要らなくなります。

RSA公開鍵に関する設定

SSL を利用しない場合にクライアントがパスワードをRSAで暗号化するための公開鍵は、ローカルにあるファイルを指定する (--server-public-key-path オプション)か、認証時にサーバーから自動取得する (--get-server-public-key オプション) 事ができます。

自動取得を有効にすると、サーバーになりすました攻撃者が自分の RSA 公開鍵を送りつけることで生パスワードを得ることができるようになります。パフォーマンスを考えてもラウンドトリップが1回ふえることになります。なので個人的には --server-public-key-path オプションをお勧めします。

なりすましサーバーにSSL接続してしまった場合にも生パスワード送信してしまうので、SSLを使わない場合は --ssl-mode=DISABLED も設定しておくと良いでしょう。

ただし、繰り返しになりますが、なりすまされてる時点でリレー攻撃可能なので、生パスワードがもれなかったらOKというわけではありません。

@methane

Goのランタイムのバグを踏んで解決しました。解決までの過程を記事にします。

同じようなランタイムのバグを踏んで、小さい再現コードを作れない場合の参考にしてください。

自分のプログラムを疑う

あるSlackチャンネルで Go で書かれたサーバーのクラッシュが話題になっているのを見つけました。その時に共有してもらったトレースバックです。

runtime: pointer 0xc007b8af97 to unused region of span span.base()=0xc004000000 span.limit=0xc004002000 span.state=1
fatal error: found bad pointer in Go heap (incorrect use of unsafe or cgo?)
runtime stack:
runtime.throw(0xc046ca, 0x3e)
        /usr/local/Cellar/go/1.11.2/libexec/src/runtime/panic.go:608 +0x72 fp=0xc0001dff00 sp=0xc0001dfed0 pc=0x42bf02
runtime.findObject(0xc007b8af97, 0x0, 0x0, 0xc005eb4780, 0x7f3d1915b7b8, 0x5)
        /usr/local/Cellar/go/1.11.2/libexec/src/runtime/mbitmap.go:399 +0x3b6 fp=0xc0001dff50 sp=0xc0001dff00 pc=0x413bf6
runtime.wbBufFlush1(0xc000047900)

(長いバージョン)

エラーメッセージに "incorrect use of unsafe or cgo?" って言われてるので、まずはそれを疑います。

cgoは使っていませんでした。 unsafe は使わないようにビルドするのは大変なので、コードをチェックアウトして怪しいところを探します。 プロジェクトのコードには見当たりません。vendoringしているコードにはたくさんありますが、このプログラムで実際に利用されてそうな部分で怪しいものはありませんでした。

また、 race はすでに疑っていて、 -race オプション付きで見つけたレースコンディションを全て潰したあとだったようです。

これでランタイムバグの可能性が高くなってきました。

修正済みバグの可能性と、最近のリグレッションの可能性を調べるため、Go 1.11.4 と Go 1.10.5 で試してもらいました。 1.11.4 ですぐに再現し、 1.10.5 では再現しなかったそうです。 もちろん再現確率が違うだけの可能性も残ってるので、リグレッションだと確定したわけではありません。

Goのデバッグ機能を利用して原因特定を試みる

時系列的には上と同時になりますが、Goが標準で持っているデバッグ機能をつかって原因特定できないか試行錯誤をします。

まず大事なのは、スタックトレースとコードを読みクラッシュした状況を理解することです。

今回のケースは、ライトバリアの実装の中で（性能のために）一旦バッファリングしていたポインタを処理する前に有効な（ヒープ内を指している）ポインタかどうかチェックしている箇所で、無効なポインタを見つけたというものです。

悪いポインタがバッファの中から見つかっているために、そのポインタがどの変数に書かれていたのかとか、どのコードによって書かれたのかがわかりません。そこで試してもらったのが、 GODEBUG 環境変数のうち invalidptr=0 と GODEBUG=gcstoptheworld=1 です。

invalidptr=0 を使うと、このポインタのチェックがなくなります。それでクラッシュしなくなれば、問題解決に時間がかかったときのワークアラウンドになります。クラッシュすれば、今度はその悪いポインタが入っている変数を特定するヒントが得られる可能性が高いです。

gcstoptheworld=1 はコンカレントGC自体を無効にするもので、ライトバリアが使われなくなるので同じく悪いポインタを利用している箇所の近くでクラッシュすることが期待できます。

結果として、どちらのオプションを使ってもクラッシュしなくなりました。ここまでの状況を整理した上で、一旦バグ報告しておきました。

https://github.com/golang/go/issues/29362

ローカルでの再現できるようにする

そろそろ手詰まり感が出てきました。腰を落ち着けて、自分で自由に使える再現環境を作ります。

docker-compose を使った開発環境構築手順を教えてもらい、現象を再現できるようになるまで試験環境との差異を調べて減らしていきます。ログの量を同じにしたところで、１日に数回クラッシュをさせられるようになりました。

反省点として、これは手詰まりになる前にさっさとやっておくべきでした。

print & throw デバッグ

runtime.wbBufFlush1 はライトバリア・バッファの中のポインタを処理する関数なので、ライトバリア・バッファにポインタを書き込む場所を探します。 runtime/mwbbuf.go はたった311行の小さいコードなので、すぐに (*wbBuf).putFast() という関数が見つかりました。ここに、 fatal error の原因になっているチェックと throw を仕込んでみます。

runtime: bad pinter: 0xc007435e93
fatal error: XXXXXX

runtime stack:
runtime.throw(0xbeaeb3, 0x6)
    /home/ubuntu/local/go/src/runtime/panic.go:608 +0x72
runtime.(*wbBuf).putFast(0xc00003b290, 0xc007435e93, 0xc007435e93, 0x7f4b766b6d88)
    /home/ubuntu/local/go/src/runtime/mwbbuf.go:143 +0x1f8
runtime.bulkBarrierBitmap(0xc0038a6fd8, 0xc0038a6fd8, 0x8, 0x0, 0xc19258)
    /home/ubuntu/local/go/src/runtime/mbitmap.go:682 +0x12d
runtime.newproc1(0xc194f0, 0xc0002c8708, 0x8, 0xc00222e780, 0x7f1edd)
    /home/ubuntu/local/go/src/runtime/proc.go:3373 +0x441
runtime.newproc.func1()
    /home/ubuntu/local/go/src/runtime/proc.go:3309 +0x4f
runtime.systemstack(0x0)
    /home/ubuntu/local/go/src/runtime/asm_amd64.s:351 +0x66
runtime.mstart()
    /home/ubuntu/local/go/src/runtime/proc.go:1229

goroutine 66219 [running]:
runtime.systemstack_switch()
    /home/ubuntu/local/go/src/runtime/asm_amd64.s:311 fp=0xc0002c86b0 sp=0xc0002c86a8 pc=0x45bb70
runtime.newproc(0xc000000008, 0xc194f0)
    /home/ubuntu/local/go/src/runtime/proc.go:3308 +0x6e fp=0xc0002c86f8 sp=0xc0002c86b0 pc=0x43750e
XXX/game/connection.Keep(0x7435e93)

これで、プロジェクトの connection.Keep 関数から runtime.newproc が呼び出され、そこから bad pointer がライトバリア・バッファに書き込まれていることがわかります。 また、よくみてみると、 bad pointer の壊れている下位バイトが、 Keep 関数の引数と完全に一致していますね。

throw を仕込む前の完全なスタックダンプ（クラッシュしたgoroutine以外の全部のgoroutineが、引数付きで書き出される）を見直してみると、さらに面白い事がわかりました。

runtime: pointer 0xc00659e432 to unused region of span span.base()=0xc004000000 span.limit=0xc004001f80 span.state=1
fatal error: found bad pointer in Go heap (incorrect use of unsafe or cgo?)

runtime stack:
runtime.throw(0xc0f417, 0x3e)
    /home/ubuntu/local/go/src/runtime/panic.go:608 +0x72 fp=0x7ff10e99fd98 sp=0x7ff10e99fd68 pc=0x42dec2
runtime.findObject(0xc00659e432, 0x0, 0x0, 0xc004ab0180, 0x7ff10d5f3e70, 0x1)

...

goroutine 29115 [runnable]:
XXX/game/connection.Keep.func1(0xc00659e432)
    XXX/game/connection/connection.go:22 fp=0xc0044a97d8 sp=0xc0044a97d0 pc=0x7f1ff0
runtime.goexit()
    /home/ubuntu/local/go/src/runtime/asm_amd64.s:1333 +0x1 fp=0xc0044a97e0 sp=0xc0044a97d8 pc=0x45dc51
created by XXX/game/connection.Keep
    XXX/game/connection/connection.go:22 +0x3d

bad pointer のアドレスと Keep.func1 の引数が完全に一致しています。 Keep 関数のコードを見てみましょう。

func Keep(playerID int32) {
    go func() { // この無名関数が Keep.func1
        err := updateAliveTime(playerID)
        if err != nil {
            logger.Errorf("Failed to keep connection. err=[%v]", err)
        }
    }()
}

なんとなく、スタックに残っていたポインタ (64bit) の下位 32bit を int32 の変数で上書きして bad pointer が生成されてそうなのがわかります。とはいえ、 int32 の変数がある場所をポインタとして扱っているのはコンパイラかランタイムのどちらかのバグのはずです。

ここまで追い詰めたら、この部分に詳しい人ならすぐに解析できるでしょう。一旦ここまでをまとめて報告しておきます。

コードリーディング＆バグ修正

ここまでくれば待っていても誰かが直してくれると思いますが、クリスマスを過ぎてしまって欧米の開発者は holiday に入ってしまっている時期だし、何より楽しいので、 newproc ... putFast までのコードを読んでいきます。

newproc1 が新しい goroutine のための G オブジェクトを用意し、親 goroutine のスタックから新しい goroutine のスタックに最初の関数の引数をコピーした上で、ライトバリアが有効なら bulkBarrierBitmap を呼び出しています。 bulkBarrierBitmap は渡されたビットマップを使ってメモリ中のポインタをライトバリア・バッファに putFast していきます。

本来なら、 Keep.func1 の引数は（クロージャ変数の） playerID int32 一つだけなので、 putFast が呼び出されるはずがありません。 bulkBarrierBitmap の呼び出しの前に print を仕込んでビットマップの内容を表示してみます。すると、 Keep.func1 は引数の長さが１ワードなのに、引数のビットマップは長さが 0 になっていました。

このスタック用のビットマップに関連するコードを読んでみると、該当するスタックの中にポインタが１つもない時は空のビットマップが使われるようでした。なので、 bulkBarrierBitmap はオーバーランして別のデータ（多分実行バイナリ上で隣に配置された別のビットマップ）を参照してしまい、int32 の変数が入っている箇所を間違えて処理しているようです。

bulkBarrierBitmap を呼び出す前にビットマップの長さが 0 でないかテストする事で問題が解消することを確認し、報告しました。

https://github.com/golang/go/issues/29362#issuecomment-449964832

パッチ送信＆再現コード作成

runtime の他の場所で似たことをしている場所を探し、自分の書いた if 文が他の場所と(> 0 か != 0 かのスタイルまで)同一であることを確認した上で、 Gerrit にパッチを送信します。

https://go-review.googlesource.com/c/go/+/155779

また、レビューアーが確認できるように、クラッシュの小さい再現コードも作ってみます。ライトバリアが常に有効になるように、ヒープ上にポインタ変数をたくさん作った上で runtime.GC() をループで呼び出します。また、スタック上に残っていたゴミポインタと int32 の値の合体で偶然 bad pointer を作るのでなく、意図的に bad pointer を作った上で、それを整数型の引数として関数を呼び出します。

残る再現条件は、長さ0のビットマップをオーバーランしたときにたまたまその場所のビットが1になっていることなのですが、この条件は Go プログラムで意図的に作り出すことが難しい。確率を上げるためにとりあえず引数を１つではなく４つにしてみたら、あっさり再現できました。

https://gist.github.com/methane/b61dcfb504d54de5bced1c6e3209a91d

理想的にはこの再現コードをリグレッション・テストに落とし込むなり、 newproc1 に対するユニットテストが書ければ完璧なのですが、この辺は Go のプログラムから直接呼び出されるのではなく Go コンパイラが呼び出しコードを生成する部分でテストが難しいので今後レビューアーと相談します。