alp 1.0.0 does not show the correct result for H20 log

[shuheiktgw]

Thank you for your great tool! 😄 I just encountered a small problem.

version

v1.0.0-rc1 or above

Problem

When I use alp v1.0.0 -rc1 for H2o ltsv log, it does not show the result like below.

[vagrant@localhost ~]$ sudo alp ltsv --file /var/log/h2o/access.log
+-------+-----+-----+-----+-----+-----+--------+-----+-----+-----+-----+-----+----+-----+-----+--------+-----------+-----------+-----------+-----------+
| COUNT | 1XX | 2XX | 3XX | 4XX | 5XX | METHOD | URI | MIN | MAX | SUM | AVG | P1 | P50 | P99 | STDDEV | MIN(BODY) | MAX(BODY) | SUM(BODY) | AVG(BODY) |
+-------+-----+-----+-----+-----+-----+--------+-----+-----+-----+-----+-----+----+-----+-----+--------+-----------+-----------+-----------+-----------+
+-------+-----+-----+-----+-----+-----+--------+-----+-----+-----+-----+-----+----+-----+-----+--------+-----------+-----------+-----------+-----------+

When I use alp v0.4.0 to the same log file instead, it shows the correct result.

[vagrant@localhost ~]$ sudo alp --file=/var/log/h2o/access.log
+-------+--------+-----------------------------------------+-----+-----+-----+-----+-----+--------+--------+--------+--------+--------+--------+--------+--------+--------------+--------------+--------------+--------------+
| COUNT | METHOD |                   URI                   | 1XX | 2XX | 3XX | 4XX | 5XX |  MIN   |  MAX   |  SUM   |  AVG   |   P1   |  P50   |  P99   | STDDEV |  MIN(BODY)   |  MAX(BODY)   |  SUM(BODY)   |  AVG(BODY)   |
+-------+--------+-----------------------------------------+-----+-----+-----+-----+-----+--------+--------+--------+--------+--------+--------+--------+--------+--------------+--------------+--------------+--------------+
|     1 | DELETE | /api/events/11/sheets/C/60/reservation  |   0 |   0 |   0 |   1 |   0 |  0.000 |  0.000 |  0.000 |  0.000 |  0.000 |  0.000 |  0.000 |  0.000 |       26.000 |       26.000 |       26.000 |       26.000 |
|    29 | GET    | /css/admin.css                          |   0 |  29 |   0 |   0 |   0 |  0.000 |  0.000 |  0.000 |  0.000 |  0.000 |  0.000 |  0.000 |  0.000 |      684.000 |      684.000 |    19836.000 |      684.000 |
|     1 | DELETE | /api/events/11/sheets/C/115/reservation |   0 |   0 |   0 |   1 |   0 |  0.000 |  0.000 |  0.000 |  0.000 |  0.000 |  0.000 |  0.000 |  0.000 |       26.000 |       26.000 |       26.000 |       26.000 |
|    29 | GET    | /css/layout.css                         |   0 |  29 |   0 |   0 |   0 |  0.000 |  0.000 |  0.000 |  0.000 |  0.000 |  0.000 |  0.000 |  0.000 |      707.000 |      707.000 |    20503.000 |      707.

/etc/h2o/h2o.conf

[vagrant@localhost ~]$ cat /etc/h2o/h2o.conf
user: isucon

access-log:
  path: /var/log/h2o/access.log
  format: "time:%t\thost:%h\tua:\"%{User-agent}i\"\tstatus:%s\treq:%r\turi:%U\treqtime:%{duration}x\tsize:%b\tmethod:%m\t"
error-log: /var/log/h2o/error.log
pid-file: /var/run/h2o/h2o.pid

hosts:
  "localhost:80":
    listen:
      port: 80
      host: 0.0.0.0
    paths:
      "/favicon.ico":
        file.file: /home/isucon/torb/webapp/static/favicon.ico
      "/css":
        file.dir: /home/isucon/torb/webapp/static/css
      "/img":
        file.dir: /home/isucon/torb/webapp/static/img
      "/js":
        file.dir: /home/isucon/torb/webapp/static/js
      "/":
        proxy.reverse.url: http://127.0.0.1:8080/
        proxy.preserve-host: ON

/var/log/h2o/access.log

[vagrant@localhost ~]$ sudo head /var/log/h2o/access.log

time:[24/Aug/2019:07:13:12 +0000]   host:172.28.128.9   ua:"isucon8q-benchmarker"   status:204  req:GET /initialize HTTP/1.1    uri:/initialize reqtime:1.606702    size:0  method:GET
time:[24/Aug/2019:07:13:13 +0000]   host:172.28.128.9   ua:"isucon8q-benchmarker"   status:200  req:GET /css/admin.css HTTP/1.1 uri:/css/admin.css  reqtime:0   size:684    method:GET
time:[24/Aug/2019:07:13:13 +0000]   host:172.28.128.9   ua:"isucon8q-benchmarker"   status:200  req:GET /css/bootstrap.min.css HTTP/1.1 uri:/css/bootstrap.min.css  reqtime:0   size:140930 method:GET
time:[24/Aug/2019:07:13:13 +0000]   host:172.28.128.9   ua:"isucon8q-benchmarker"   status:200  req:GET /css/layout.css HTTP/1.1    uri:/css/layout.css reqtime:0   size:707    method:GET
time:[24/Aug/2019:07:13:13 +0000]   host:172.28.128.9   ua:"isucon8q-benchmarker"   status:200  req:GET /favicon.ico HTTP/1.1   uri:/favicon.ico    reqtime:0   size:1092   method:GET
time:[24/Aug/2019:07:13:13 +0000]   host:172.28.128.9   ua:"isucon8q-benchmarker"   status:200  req:GET /js/admin.js HTTP/1.1   uri:/js/admin.js    reqtime:0   size:8454   method:GET
time:[24/Aug/2019:07:13:13 +0000]   host:172.28.128.9   ua:"isucon8q-benchmarker"   status:200  req:GET /js/app.js HTTP/1.1 uri:/js/app.js  reqtime:0   size:10204  method:GET
time:[24/Aug/2019:07:13:13 +0000]   host:172.28.128.9   ua:"isucon8q-benchmarker"   status:200  req:GET /js/bootstrap-waitingfor.min.js HTTP/1.1    uri:/js/bootstrap-waitingfor.min.js reqtime:0size:2074  method:GET
time:[24/Aug/2019:07:13:13 +0000]   host:172.28.128.9   ua:"isucon8q-benchmarker"   status:200  req:GET /js/bootstrap.bundle.min.js HTTP/1.1    uri:/js/bootstrap.bundle.min.js reqtime:0   size:70682  method:GET

[shuheiktgw]

I'll check the source code later, but please let me know if you know what is going on! 👍

[tkuchiki]

@shuheiktgw Thank you for contacting me! It was undocumented so I added it.

https://github.com/tkuchiki/alp/blob/master/docs/how_to_difference_between_v0_4_0_and_v1_0_0.ja.md#v040-%E3%81%A8-v100-%E3%81%AE%E9%81%95%E3%81%84

LTSV で apptime ラベルの値がなかったら reqtime ラベルを使うようにする挙動を、apptime ラベルのみ参照するように変更

If you change the format as follows, it should operate.

- "time:%t\thost:%h\tua:\"%{User-agent}i\"\tstatus:%s\treq:%r\turi:%U\treqtime:%{duration}x\tsize:%b\tmethod:%m\t"
+ "time:%t\thost:%h\tua:\"%{User-agent}i\"\tstatus:%s\treq:%r\turi:%U\tapptime:%{duration}x\tsize:%b\tmethod:%m\t"

[shuheiktgw]

Thanks for your quick reply! 😄 I'll close this issue! 👍

[tkuchiki]

@shuheiktgw I'm sorry.

You can also as follows:

reqtime ラベルを使っている場合は、--apptime-label reqtime または --config config.yml で参照するラベルを指定してください

--config の例

https://github.com/tkuchiki/alp/blob/master/docs/how_to_difference_between_v0_4_0_and_v1_0_0.ja.md#v040-%E3%81%A8-v100-%E3%81%AE%E9%81%95%E3%81%84