tech::hexagram

personal note for technical issue.

iPhoneをバッテリ交換に出したらiOSのバグに遭遇した

譲ってもらった中古のiPhone5sがバッテリの持ちが酷く、更にLightningケーブルを抜き差しすると極端にバッテリ残量の増減が変わってだいぶヘタっていたので今日バッテリ交換をお願いしてきた。このiPhoneはサブ機として運用している。

お願いした業者さんは あいさぽ というiPhone修理を専門に行っている所。バッテリ交換だけなら5000円ほどで済むのでかなり良心的なお値段設定。

夕方に修理を依頼し、その後ジムに寄って一汗かいたあと受取に戻り、動作確認をするとなぜか電源ボタンとボリュームボタンが効かないという始末。修理に出す前は正常に動いていたので何かがおかしい…

ちなみにiPhoneのスペックは下記。

  • iPhone5s 32GB
  • iOSのバージョン: 11.0.2
  • キャリア: ドコモ29.0
  • モデル: ME336J/A
  • SIMなし、Wi-Fi運用

試行錯誤していると、他の電源ボタンを使う操作として強制再起動はかかるという不思議な感じ。このことから、ハードウェアの問題ではなくソフトウェアの問題ではないかと考え始めた。

画面をよく見ると、電池交換をして再起動をしているので時計の設定時刻が初期化されていた。これが怪しいと思ったので、手元のSIMが入った別のiPhoneテザリングさせてWi-Fiに接続した状態にし、時刻合わせを行ったところビンゴ。時刻合わせを行ってからは電源ボタンとボリュームボタンが効くようになったのだ。

iOSのバージョンが 11.0.2 と11系リリース直後のままで不安定なバージョンを使用していた自分にも原因の一端があるが、かなり焦った。。

このあたりの勘が効くのは、普段不具合の調査を行ったりしている職業病なのかもしれない…

初めてOSSにコミットした話

mariaex というElixirのMySQLライブラリにPull Requestを送って、無事に3日前にmergeされた。初めてのOSS貢献で感慨深かったので記事に書いておこうと思う。

github.com

(※@hashijun は会社用のGithubアカウント)

きっかけ

今年の2月頃、業務中にとあるDBのテーブルを設計していて、業務ロジックから生まれる複雑なfieldをどう保存するか悩んでいた。関わっていたのはリリース前のとあるElixir製プロダクト。そのタイミングで保存すべきfieldを絞り込み、テーブルを設計してPull Requestを出した。schemaの中にカラム数は結構あった。

設計したテーブルをレビューしてもらったところ、「それ、まとめてJSONカラム使ったら良いんじゃない?」とベテランの同僚エンジニアから指摘を受けた。確かに、今後カジュアルにカラムを追加したり削除する上で都合が良いので、指摘に沿ってJSONカラムを利用することに。

そのプロダクトではMySQLのライブラリに mariaex を利用していたが、実装当初はJSONカラムがunsupportedだった。

github.com

関連するissueが立っており、repositoryのmaintainerが実装した commit が残っていた(Pull Requestは出ておらず)ため、これを元にmasterからブランチを切って差分を作ってみることに。

試行錯誤を重ねた上でPull Requestを出したが、mergeされるまですんなりとはいかなかった。

github.com

続きを読む

さくらのVPS@Ubuntu14.04でmysqlが起動できなかった

ansibleを利用してmysqlをインストールしていたが、どうもmysqlの起動でコケてしまっていた。 直接ログインして sudo service mysql start を実行してもうんともすんともいわず、困っていた。

mysql.err を見てみると1つWARNINGが出ていたが特に関係のあるものではない。

% sudo tail -n 20 /var/log/mysql.err
171001 22:47:14 mysqld_safe Starting mysqld daemon with databases from /var/lib/mysql
2017-10-01 22:47:14 0 [Warning] TIMESTAMP with implicit DEFAULT value is deprecated. Please use --explicit_defaults_for_timestamp server option (see documentation for more details).
2017-10-01 22:47:14 0 [Note] /usr/sbin/mysqld (mysqld 5.6.37-log) starting as process 24154 ...
171001 22:47:16 mysqld_safe mysqld from pid file /var/run/mysqld/mysqld.pid ended

my.cnf に下記のオプションを追加したことでWARNINGは解消されたが、依然として起動ができなかった。

explicit_defaults_for_timestamp: 1

困ったなと思って syslog を見てみると気になる内容が。

% sudo tail -n 20 /var/log/syslog
Oct  9 14:34:38 www4184uf kernel: [665121.153306] type=1400 audit(1507527278.123:68): apparmor="DENIED" operation="open" profile="/usr/sbin/mysqld" name="/var/log/mysql.err" pid=25878 comm="mysqld" requested_mask="c" denied_mask="c" fsuid=105 ouid=105
Oct  9 14:34:38 www4184uf kernel: [665121.153318] type=1400 audit(1507527278.123:69): apparmor="DENIED" operation="open" profile="/usr/sbin/mysqld" name="/var/log/mysql.err" pid=25878 comm="mysqld" requested_mask="c" denied_mask="c" fsuid=105 ouid=105
Oct  9 14:34:38 www4184uf kernel: [665121.153325] type=1400 audit(1507527278.123:70): apparmor="DENIED" operation="open" profile="/usr/sbin/mysqld" name="/var/log/mysql.err" pid=25878 comm="mysqld" requested_mask="c" denied_mask="c" fsuid=105 ouid=105

apparmorというプロセスに起動を止められている…?WikiPediaによれば、このプロセスはセキュリティを向上させるプログラムとのこと。

AppArmor (Application Armor) とは、Linux Security Modulesの一種であり、各プログラムにセキュリティプロファイルを結びつけ、プログラムのできることに制限をかけるプログラムである。プロファイルは、ネットワークアクセス、Raw socket アクセス、ファイルへの読み書き実行などの機能を制限することができる。

ref. https://ja.wikipedia.org/wiki/AppArmor

とりあえずmysqldに関してapparmorの制限を止める。

sudo ln -s /etc/apparmor.d/usr.sbin.mysqld /etc/apparmor.d/disable/
sudo apparmor_parser -R /etc/apparmor.d/usr.sbin.mysqld

再度mysqlを立ち上げようとすると再び止まってしまっていたので mysql.err を見る。

% sudo tail -n 20 /var/log/mysql.err
/usr/sbin/mysqld: Table 'mysql.plugin' doesn't exist
2017-10-09 15:21:34 15344 [ERROR] Can't open the mysql.plugin table. Please run mysql_upgrade to create it.
2017-10-09 15:21:34 15344 [Note] InnoDB: Using atomics to ref count buffer pool pages
2017-10-09 15:21:34 15344 [Note] InnoDB: The InnoDB memory heap is disabled
2017-10-09 15:21:34 15344 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2017-10-09 15:21:34 15344 [Note] InnoDB: Memory barrier is not used
2017-10-09 15:21:34 15344 [Note] InnoDB: Compressed tables use zlib 1.2.3
2017-10-09 15:21:34 15344 [Note] InnoDB: Using Linux native AIO
2017-10-09 15:21:34 15344 [Note] InnoDB: Using CPU crc32 instructions
2017-10-09 15:21:34 15344 [Note] InnoDB: Initializing buffer pool, size = 256.0M
2017-10-09 15:21:34 15344 [Note] InnoDB: Completed initialization of buffer pool
2017-10-09 15:21:34 15344 [Note] InnoDB: Highest supported file format is Barracuda.
2017-10-09 15:21:34 15344 [Note] InnoDB: 128 rollback segment(s) are active.
2017-10-09 15:21:34 15344 [Note] InnoDB: Waiting for purge to start
2017-10-09 15:21:34 15344 [Note] InnoDB: 5.6.37 started; log sequence number 1601046
2017-10-09 15:21:34 15344 [Note] Server hostname (bind-address): '0.0.0.0'; port: 3306
2017-10-09 15:21:34 15344 [Note]   - '0.0.0.0' resolves to '0.0.0.0';
2017-10-09 15:21:34 15344 [Note] Server socket created on IP: '0.0.0.0'.
2017-10-09 15:21:34 15344 [ERROR] Fatal error: Can't open and lock privilege tables: Table 'mysql.user' doesn't exist
171009 15:21:34 mysqld_safe mysqld from pid file /var/run/mysqld/mysqld.pid ended

/var/lib/mysql 配下の内容を見てみると、古いplaybookの適用時の残骸が残っていたようで、ファイルの作成日時がばらばらになっていた。

% ls -la /var/lib/mysql
total 143380
drwxr-xr-x  4 mysql mysql     4096 10月  9 15:21 .
drwxr-xr-x 50 root  root      4096 10月  1 22:12 ..
-rw-rw----  1 mysql mysql       56 10月  1 21:37 auto.cnf
-rw-rw----  1 mysql mysql 67108864 10月  9 15:21 ib_logfile0
-rw-rw----  1 mysql mysql 67108864 10月  1 22:47 ib_logfile1
-rw-rw----  1 mysql mysql 12582912 10月  1 23:09 ibdata1
drwx------  2 mysql mysql     4096 10月  1 21:30 mysql
drwx------  2 mysql mysql     4096 10月  1 21:30 test

一旦きれいな状態からインストール作業を試みるためディレクトリごと削除し、mysql-common, mysql-serverのpackageを削除し、再度ansibleを実行してみた。するとmysqlのplaybookは正常に最後まで適用できた。

色々とハマりどころがあったのでなかなか厄介だった。。

MTのテンプレートタグの変数展開

セットした値を mtFor で利用したい場合は、変数名を $ で囲うと展開される。

<mt:SetVar name="current_year" value="2017">
<mt:For var="year" from="1990" to="$current_year" increment="1">
...
</mt:For>

追記: MTテンプレートタグで去年の年を取得する方法として、 MTDate を利用すると良いと一度書いたものの、これは

再構築した日時を表示します。更新日時を表示したいときなどに利用します。

とあるので、「アクセスした日」を起点としての判断ができないらしい。

git fetchで、unable to update local refとエラーが出た場合の対処法

リモートでブランチが削除されたのか、git fetchしようとした時にエラーが出た。 git remote prune origin / git fetch originで解決。

error: there are still refs under 'refs/remotes/origin/XXX`
 ! [new branch]      XXX    -> origin/XXX  (unable to update local ref)
$ git remote prune origin
...

$ git fetch origin
From github.com:xxx/xxx
 * [new branch]      XXX    -> origin/XXX

distilleryを利用したリリースビルドから、command経由でmoduleを実行する際のハマりどころ

2点ハマりどころがあったのでまとめておく。

リリースビルドに含まれないmoduleを実行していないか

/path/to/bin$ ./some command Elixir.Some.Module run ...
{"init terminating in do_boot",{undef,[{'Elixir.Some.Module',application,[],[]},...,{line,24}]},{init,start_em,1,[]},{init,do_boot,3,[]}]}}
init terminating in do_boot ()

/path/to/lib/some 配下で、 Elixir.Some.Module.beam ファイルが生成されているかどうか確認する。

ETSの上限に達していないか

/path/to/bin$ ./some command Elixir.Some.Module run ...
{"init terminating in do_boot",{{badmatch,{error,{some,{{shutdown,{failed_to_start_child,'XXXX',{shutdown,{failed_to_start_child,'XXXX',{system_limit,[{ets,new,['XXXXXX',[set,public,named_table,{read_concurrency,true}]],[]},...{init,start_em,1,[]},{init,do_boot,3,[]}]}}
init terminating in do_boot ()

ETSの上限に達している場合、上記のようなエラーが出る。ETSの上限は ERL_OPTS から "+e 16384" のように渡すことが出来る。

github.com

distilleryのビルドの設定で、 erl_opts から設定を追加する。

github.com

Exqのenqueueのプロセスを追ってみた

仕事に必要だったのでメモ書き程度に残しておく。

Exq というRedisを利用したJob queueライブラリのコードリーディング。

  • Exq.enqueue/4 : use Exq.Enqueuer.EnqueueApi とあるので、その中に実体がある。
# Exq.Enqueuer.EnqueueApi

def enqueue(pid, queue, worker, args), do: enqueue(pid, queue, worker, args, @default_options)

def enqueue(pid, queue, worker, args, options) do
  GenServer.call(pid, {:enqueue, queue, worker, args, options}, Config.get(:genserver_timeout))
end

GenServer の仕組みで :enqueue をメッセージとして送信する。 handle_call:enqueue を処理しているメソッドを探す。

# Exq.Manager.Server

def handle_call({:enqueue, queue, worker, args, options}, from, state) do
  Enqueuer.enqueue(state.enqueuer, from, queue, worker, args, options)
  {:noreply, state, 10}
end
  • Exq.Enqueuer.enqueue: use Exq.Enqueuer.EnqueueApi とあるので、その中に実体がある。
# Exq.Enqueuer.EnqueueApi.enqueue

def enqueue(pid, from, queue, worker, args, options) do
  GenServer.cast(pid, {:enqueue, from, queue, worker, args, options})
end

handle_cast:enqueue を処理しているメソッドを探す。

# Exq.Enqueuer.Server

def handle_cast({:enqueue, from, queue, worker, args, options}, state) do
  response = JobQueue.enqueue(state.redis, state.namespace, queue, worker, args, options)
  GenServer.reply(from, response)
  {:noreply, state}
end
# Exq.Redis.JobQueue
def enqueue(redis, namespace, queue, worker, args, options) do
  {jid, job_serialized} = to_job_serialized(queue, worker, args, options)
  case enqueue(redis, namespace, queue, job_serialized) do
    \:ok    -> {:ok, jid}
    other  -> other
  end
end
def enqueue(redis, namespace, queue, job_serialized) do
  try do
    response = Connection.qp(redis, [
      ["SADD", full_key(namespace, "queues"), queue],
      ["LPUSH", queue_key(namespace, queue), job_serialized]])

    case response do
      {:ok, [%Redix.Error{}, %Redix.Error{}]} = error -> error
      {:ok, [%Redix.Error{}, _]} = error -> error
      {:ok, [_, %Redix.Error{}]} = error -> error
      {:ok, [_, _]} -> \:ok
      other    -> other
    end
  catch
    :exit, e ->
      Logger.info("Error enqueueing -  #{Kernel.inspect e}")
      {:error, :timeout}
  end
end

def to_job_serialized(queue, worker, args, options) do
  to_job_serialized(queue, worker, args, options, Time.unix_seconds)
end
def to_job_serialized(queue, worker, args, options, enqueued_at) do
  jid = UUID.uuid4
  retry = Keyword.get_lazy(options, :max_retries, fn() -> Config.get(:max_retries) end)
  job = %{queue: queue, retry: retry, class: worker, args: args, jid: jid, enqueued_at: enqueued_at}
  {jid, Config.serializer.encode!(job)}
end

というわけで Exq.Redis.JobQueue.enqueue/4 がほぼ実体であることがわかった。Redisに投げているコマンドの詳細は下記となる。


ちなみに dequeue の処理を追うつもりであったが hexdoc に詳細な解説があったので大体の処理の流れは理解できた。