marblejenkaの日記

balmysundaycandy-morelowlevel-logger-beta-r68.jar をリリースしました

appengineから離れて二週間、なにか充実感のない生活を送っていました。仕事が忙しいとか、そういう事情はありますが、それでもなお平静を保つためにappengineを触ろうと思いました。

ということで、OKAMOTO氏の記事に触発されてつくりたいつくりたいと思っていたmakeSyncCallを経由するサービス呼び出しのオブジェクトを捕捉するロガーを作りました。

ダウンロードはこちら。

コンセプトは、

・これまで手動で構築してはtoStringしていたrpc callのオブジェクトを自動的に捕捉する。low level apiやその上位層のrpc callも捕捉する。

・low level apiみたいな上位のサービスラッパを使っている人も簡単にこっちの世界に来れるようにする

これまでは、ソースを追っかけてサービス呼び出しの全貌をとらえることが主眼にありました。が、このアプローチで内部的に持っている・持ちうる状態をソースから想像するのは難しいです。このapiを使ってもすべての状態を掌握することはできませんが、いきなり手探りでやるよりはよほどましです。

また、自動的にlow level apiあるいはさらに上位のapiのrpc callを捕捉することにより、サービス呼び出しでなにをやっているのか理解する一助になると思います。

いまの実装では、

・makeSyncCallを経由するサービス呼び出しのみを捕捉。asyncのをxmppしたらなんかうまみがない。1.3.0のapiはまだちゃんと見ていないのでなんともですが、まだasyncを使うlow level apiはないのでは？ということもありそうしています。

・datastoreの呼び出しのみを捕捉。これは、urlfetchなどのgenerated messageを継承するprotocol bufferの取り扱いに苦心していることもありますが、そもそも、ほかの連中はわりと素直なので、logをとる優先順位があまり高くないからです。そのうち対応すると思います。

・AddActionについては、なぜかclass no def found errorとなってしまうので、除外しています。これふしぎ。

・session enableになっていると、datastoreへのセッションの格納も捕捉します。これは、まぁしょうがないでしょう。

使い方は、

・ダウンロードしたjarをWEB-INF/lib配下に置く

・eclipseの人はclasspathを通す

・appengine-web.xmlに下記の記述を追加する

<inbound-services>

<service>xmpp_message</service>

</inbound-services>

・ApiProxy.setDelegate(new ProtocolBufferLogDelegate(anata.no.mail.address)); を実行する

・google talkを立ち上げてanata.no.mail.addressを招待する

です。

これ以降！datastoreへのサービス呼び出しは！！google talkにその詳細をおくりつけられることになるのだ！！！

解除したいときは、

ApiProxy.setDelegate(ProtocolBufferLogDelegate.getOriginal());

とするか、再度デプロイすると元に戻ります。

では、ちょっとしたサンプルを。@shin1ogawaさんにお願いされていたこれ、のgithubのコードを実行したときのログを記載します。low level apiの呼び出しによって何がおこっているか、ソースとつきあわせて想像すると楽しめますよ。

・・・と思ったら、google talkは出てきたメッセージをコピーできないのです。これは困りました。うーん。ということで、ちょっと拡張しました。

ApiProxy.setDelegate(new ProtocolBufferLogDelegate(new SimpleLogger()));

とすると、log.infoで出ます。突貫なのでインターフェイスあわせるとかそういうことはしてませんがなにか？

ApiProxy.setDelegate(new ProtocolBufferLogDelegate(new StandardOutputLogger()));

とすると、sysoutで出ます。ローカル向けですね。

やっぱり、productionで試したいので、SimpleLoggerで出した結果を貼付けます。

ajn3_01

#

12-17 10:55AM 49.200

balmysundaycandy.more.low.level.logger.sender.SimpleLogger log: ************************************

== servicename ==

datastore_v3

== methodname ==

AllocateIds

== request ==

model_key <

app: "balmysundaycandy"

path <

Element {

type: "parent"

name: "ignored"

}

>

>

size: 1

== response ==

start: 15007

end: 15007

#

I 12-17 10:55AM 49.261

balmysundaycandy.more.low.level.logger.sender.SimpleLogger log: ************************************

== servicename ==

datastore_v3

== methodname ==

AllocateIds

== request ==

model_key <

app: "balmysundaycandy"

path <

Element {

type: "parent"

id: 15007

}

Element {

type: "child"

name: "ignored"

}

>

>

size: 1

== response ==

start: 1

end: 1

#

I 12-17 10:55AM 49.625

balmysundaycandy.more.low.level.logger.sender.SimpleLogger log: ************************************

== servicename ==

datastore_v3

== methodname ==

Put

== request ==

entity <

key <

app: "balmysundaycandy"

path <

Element {

type: "parent"

id: 15007

}

Element {

type: "child"

id: 1

}

>

>

entity_group <

Element {

type: "parent"

id: 15007

}

>

>

== response ==

key <

app: "balmysundaycandy"

path <

Element {

type: "parent"

id: 15007

}

Element {

type: "child"

id: 1

}

>

>

cost <

index_writes: 1

index_write_bytes: 1

entity_writes: 1

entity_write_bytes: 318

>

ajn3_02

#

12-17 10:58AM 38.581

balmysundaycandy.more.low.level.logger.sender.SimpleLogger log: ************************************

== servicename ==

datastore_v3

== methodname ==

AllocateIds

== request ==

model_key <

app: "balmysundaycandy"

path <

Element {

type: "parent"

name: "ignored"

}

>

>

size: 1

== response ==

start: 16006

end: 16006

#

I 12-17 10:58AM 38.625

balmysundaycandy.more.low.level.logger.sender.SimpleLogger log: ************************************

== servicename ==

datastore_v3

== methodname ==

AllocateIds

== request ==

model_key <

app: "balmysundaycandy"

path <

Element {

type: "parent"

id: 16006

}

Element {

type: "child"

name: "ignored"

}

>

>

size: 1

== response ==

start: 1

end: 1

#

I 12-17 10:58AM 38.646

balmysundaycandy.more.low.level.logger.sender.SimpleLogger log: ************************************

== servicename ==

datastore_v3

== methodname ==

BeginTransaction

== request ==

== response ==

handle: 0xe99cea1e678995af

#

I 12-17 10:58AM 38.703

balmysundaycandy.more.low.level.logger.sender.SimpleLogger log: ************************************

== servicename ==

datastore_v3

== methodname ==

Put

== request ==

entity <

key <

app: "balmysundaycandy"

path <

Element {

type: "parent"

id: 16006

}

Element {

type: "child"

id: 1

}

>

>

entity_group <

Element {

type: "parent"

id: 16006

}

>

>

transaction <

handle: 0xe99cea1e678995af

>

== response ==

key <

app: "balmysundaycandy"

path <

Element {

type: "parent"

id: 16006

}

Element {

type: "child"

id: 1

}

>

>

cost <

index_writes: 0

index_write_bytes: 0

entity_writes: 0

entity_write_bytes: 0

>

#

I 12-17 10:58AM 38.743

balmysundaycandy.more.low.level.logger.sender.SimpleLogger log: ************************************

== servicename ==

datastore_v3

== methodname ==

Commit

== request ==

handle: 0xe99cea1e678995af

== response ==

cost <

index_writes: 1

index_write_bytes: 1

entity_writes: 1

entity_write_bytes: 318

>

#

I 12-17 10:58AM 38.785

balmysundaycandy.more.low.level.logger.sender.SimpleLogger log: ************************************

== servicename ==

datastore_v3

== methodname ==

Get

== request ==

key <

app: "balmysundaycandy"

path <

Element {

type: "parent"

id: 16006

}

Element {

type: "child"

id: 1

}

>

>

== response ==

Entity {

entity <

key <

app: "balmysundaycandy"

path <

Element {

type: "parent"

id: 16006

}

Element {

type: "child"

id: 1

}

>

>

entity_group <

Element {

type: "parent"

id: 16006

}

>

>

}

#

I 12-17 10:58AM 38.861

balmysundaycandy.more.low.level.logger.sender.SimpleLogger log: ************************************

== servicename ==

datastore_v3

== methodname ==

BeginTransaction

== request ==

== response ==

handle: 0x84b71ab4839d5e94

#

I 12-17 10:58AM 38.944

balmysundaycandy.more.low.level.logger.sender.SimpleLogger log: ************************************

== servicename ==

datastore_v3

== methodname ==

Put

== request ==

entity <

key <

app: "balmysundaycandy"

path <

Element {

type: "parent"

id: 16006

}

Element {

type: "child"

id: 1

}

>

>

entity_group <

Element {

type: "parent"

id: 16006

}

>

property <

name: "prop"

value <

stringValue: "a"

>

multiple: false

>

>

transaction <

handle: 0x84b71ab4839d5e94

>

== response ==

key <

app: "balmysundaycandy"

path <

Element {

type: "parent"

id: 16006

}

Element {

type: "child"

id: 1

}

>

>

cost <

index_writes: 0

index_write_bytes: 0

entity_writes: 0

entity_write_bytes: 0

>

#

I 12-17 10:58AM 38.998

balmysundaycandy.more.low.level.logger.sender.SimpleLogger log: ************************************

== servicename ==

datastore_v3

== methodname ==

Commit

== request ==

handle: 0x84b71ab4839d5e94

== response ==

cost <

index_writes: 2

index_write_bytes: 2

entity_writes: 1

entity_write_bytes: 333

>

ajn3_03

#

12-17 10:58AM 42.931

balmysundaycandy.more.low.level.logger.sender.SimpleLogger log: ************************************

== servicename ==

datastore_v3

== methodname ==

BeginTransaction

== request ==

== response ==

handle: 0xea8d1355f936dae4

#

I 12-17 10:58AM 42.956

balmysundaycandy.more.low.level.logger.sender.SimpleLogger log: ************************************

== servicename ==

datastore_v3

== methodname ==

Put

== request ==

entity <

key <

app: "balmysundaycandy"

path <

Element {

type: "parent"

name: "a"

}

Element {

type: "child"

name: "a"

}

>

>

entity_group <

Element {

type: "parent"

name: "a"

}

>

>

transaction <

handle: 0xea8d1355f936dae4

>

== response ==

key <

app: "balmysundaycandy"

path <

Element {

type: "parent"

name: "a"

}

Element {

type: "child"

name: "a"

}

>

>

cost <

index_writes: 0

index_write_bytes: 0

entity_writes: 0

entity_write_bytes: 0

>

#

I 12-17 10:58AM 43.001

balmysundaycandy.more.low.level.logger.sender.SimpleLogger log: ************************************

== servicename ==

datastore_v3

== methodname ==

Commit

== request ==

handle: 0xea8d1355f936dae4

== response ==

cost <

index_writes: 1

index_write_bytes: 1

entity_writes: 1

entity_write_bytes: 318

>

#

I 12-17 10:58AM 43.020

balmysundaycandy.more.low.level.logger.sender.SimpleLogger log: ************************************

== servicename ==

datastore_v3

== methodname ==

Get

== request ==

key <

app: "balmysundaycandy"

path <

Element {

type: "parent"

name: "a"

}

Element {

type: "child"

name: "a"

}

>

>

== response ==

Entity {

entity <

key <

app: "balmysundaycandy"

path <

Element {

type: "parent"

name: "a"

}

Element {

type: "child"

name: "a"

}

>

>

entity_group <

Element {

type: "parent"

name: "a"

}

>

>

}

#

I 12-17 10:58AM 43.032

balmysundaycandy.more.low.level.logger.sender.SimpleLogger log: ************************************

== servicename ==

datastore_v3

== methodname ==

BeginTransaction

== request ==

== response ==

handle: 0x109a85c543ca64ee

#

I 12-17 10:58AM 43.053

balmysundaycandy.more.low.level.logger.sender.SimpleLogger log: ************************************

== servicename ==

datastore_v3

== methodname ==

Put

== request ==

entity <

key <

app: "balmysundaycandy"

path <

Element {

type: "parent"

name: "a"

}

Element {

type: "child"

name: "a"

}

>

>

entity_group <

Element {

type: "parent"

name: "a"

}

>

property <

name: "prop"

value <

stringValue: "a"

>

multiple: false

>

>

transaction <

handle: 0x109a85c543ca64ee

>

== response ==

key <

app: "balmysundaycandy"

path <

Element {

type: "parent"

name: "a"

}

Element {

type: "child"

name: "a"

}

>

>

cost <

index_writes: 0

index_write_bytes: 0

entity_writes: 0

entity_write_bytes: 0

>

#

I 12-17 10:58AM 43.101

balmysundaycandy.more.low.level.logger.sender.SimpleLogger log: ************************************

== servicename ==

datastore_v3

== methodname ==

Commit

== request ==

handle: 0x109a85c543ca64ee

== response ==

cost <

index_writes: 2

index_write_bytes: 2

entity_writes: 1

entity_write_bytes: 333

>

いろいろ考察したいところですが、さすがに時間も時間なのでまた明日。

Permalink | コメント(0) | トラックバック(0) | 04:05