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

Run wechaty-getting-started failed on Ubuntu 20.04.1 #254

Closed
RustChater opened this issue Mar 27, 2022 · 7 comments
Closed

Run wechaty-getting-started failed on Ubuntu 20.04.1 #254

RustChater opened this issue Mar 27, 2022 · 7 comments
Labels
bug

Comments

@RustChater
Copy link

When I try example (https://github.com/wechaty/getting-started.git) on Ubuntu 20(AWS), got error.

Env:

OS: UBuntu 20.04.1
Docker: 19.03.15 / 20.x
wechaty: wechaty@1.18.1

First, I start docker image wechaty successfully:

sudo docker run \
-ti \
--name friday_wechaty_puppet_service_token_gateway \
--rm \
--privileged \
--network=host \
-e WECHATY_LOG=verbose \
-e WECHATY_PUPPET=wechaty-puppet-padlocal \
-e WECHATY_PUPPET_SERVICE_NO_TLS_INSECURE_SERVER=true \
-e WECHATY_PUPPET_PADLOCAL_TOKEN=puppet_padlocal_58658eaxxx \
-e WECHATY_TOKEN=insecure_ebd42481-xxxxx \
wechaty/wechaty:0.78

later, I tried wechaty:latest versions and got other errors.

Then, I installed libraries that the browser dependency related.

sudo apt-get install -y gconf-service libasound2 libatk1.0-0 libatk-bridge2.0-0 libc6 libcairo2 libcups2 libdbus-1-3 libexpat1 libfontconfig1 libgcc1 libgconf-2-4 libgdk-pixbuf2.0-0 libglib2.0-0 libgtk-3-0 libnspr4 libpango-1.0-0 libpangocairo-1.0-0 libstdc++6 libx11-6 libx11-xcb1 libxcb1 libxcomposite1 libxcursor1 libxdamage1 libxext6 libxfixes3 libxi6 libxrandr2 libxrender1 libxss1 libxtst6 ca-certificates fonts-liberation libappindicator1 libnss3 lsb-release xdg-utils wget
sudo apt-get install -y libgbm-dev

Last, run npm start:

git clone https://github.com/wechaty/getting-started.git
npm install
WECHATY_LOG=verbose \
WECHATY_PUPPET=wechaty-puppet-service \
WECHATY_PUPPET_SERVICE_TOKEN=insecure_ebd42481-xxxxx \
WECHATY_PUPPET_SERVICE_NO_TLS_INSECURE_CLIENT=true \
npm start

Got error:

...
03:19:05 VERB PuppetService contactRawPayload(qq62xx)
03:19:05 VERB PuppetService contactRawPayload(paryxx)
03:19:05 VERB PuppetService contactRawPayload(wxid_v3kp0xxx)
03:19:05 VERB PuppetService contactRawPayload(wxid_l0lv2xxx)
03:19:05 VERB PuppetService contactRawPayload(wxid_1rpg17xx)
03:19:05 VERB PuppetService contactRawPayload(wxid_riezvkxx)
03:19:05 VERB PuppetService contactRawPayload(wxid_y1r8yaxx)
03:19:05 VERB PuppetService contactRawPayload(wxid_15p3dqxxx)
03:19:05 VERB PuppetService contactRawPayload(wxid_snb43yxxx)
03:19:05 VERB PuppetService contactRawPayload(wxid_czr4twbxxx)
03:19:05 VERB PuppetService contactRawPayload(michael_wuxxx)
03:19:05 VERB PuppetService contactRawPayload(wxid_dcy8uxxx)
03:19:05 VERB PuppetService contactRawPayload(wxid_z20qxx)
03:19:05 WARN Room findAll() message.ready() rejection: TypeError: response.getWeixin is not a function
03:19:05 ERR Config ###########################
03:19:05 ERR Config Wechaty unhandledRejection: GError: message not found for id: 48991355xxxxx
at Function.from (file:///root/wechaty/getting-started/node_modules/gerror/src/gerror/gerror.ts:69:17)
at PuppetService.<anonymous> (file:///root/wechaty/getting-started/node_modules/wechaty/src/wechaty-mixins/puppet-mixin.ts:277:45)
    at processTicksAndRejections (node:internal/process/task_queues:96:5) [object Promise]
    03:19:05 ERR Config ###########################
    03:19:05 ERR Config process.on(unhandledRejection) promise.catch(message not found for id: 48991355xxxxx)
    Config GError: message not found for id: 48991355xxxxx
    at Function.from (file:///root/wechaty/getting-started/node_modules/gerror/src/gerror/gerror.ts:69:17)
    at PuppetService.<anonymous> (file:///root/wechaty/getting-started/node_modules/wechaty/src/wechaty-mixins/puppet-mixin.ts:277:45)
        at processTicksAndRejections (node:internal/process/task_queues:96:5) {
        code: 2,
        details: 'GError: message not found for id: 48991355xxxxx\n' +
        '    at Function.from (file:///root/wechaty/getting-started/node_modules/gerror/src/gerror/gerror.ts:69:17)\n' +
        '    at PuppetService.<anonymous> (file:///root/wechaty/getting-started/node_modules/wechaty/src/wechaty-mixins/puppet-mixin.ts:277:45)\n' +
            '    at processTicksAndRejections (node:internal/process/task_queues:96:5)'
            }
03:19:20 VERB PuppetService onGrpcStreamEvent({type:EVENT_TYPE_HEARTBEAT(1), payload(len:29)})
03:19:35 VERB PuppetService onGrpcStreamEvent({type:EVENT_TYPE_HEARTBEAT(1), payload(len:29)})
@huan
Copy link
Member

huan commented Mar 29, 2022 •
edited

According to

03:19:05 WARN Room findAll() message.ready() rejection: TypeError: response.getWeixin is not a function

I believe this problem was introduced by the implementation related to:

Could you please post the output messages of the below commands?

npm ls wechaty wechaty-puppet wechaty-grpc wechaty-puppet-service

@RustChater
Copy link
Author 

wechaty-getting-started@1.18.4 /root/wechaty/getting-started
├─┬ wechaty-cqrs@0.7.5
│ ├─┬ wechaty-redux@1.19.7
│ │ ├── wechaty-puppet@1.18.3 deduped
│ │ └── wechaty@1.18.1 deduped
│ └── wechaty@1.18.1 deduped
├─┬ wechaty-puppet-mock@1.18.2
│ └── wechaty-puppet@1.18.3
├─┬ wechaty-puppet-oicq@1.10.2
│ └── wechaty-puppet@1.18.3 deduped
├─┬ wechaty-puppet-walnut@1.11.8
│ └── wechaty-puppet@1.18.3 deduped
├─┬ wechaty-puppet-wechat@1.18.1
│ └── wechaty-puppet@1.18.3 deduped
├─┬ wechaty-puppet-wechat4u@1.11.1
│ └── wechaty-puppet@1.18.3 deduped
├─┬ wechaty-puppet-whatsapp@1.11.77
│ └── wechaty-puppet@0.41.9
├─┬ wechaty-puppet-xp@1.10.20
│ └── wechaty-puppet@1.18.3 deduped
└─┬ wechaty@1.18.1
  ├─┬ wechaty-puppet-service@1.18.2
  │ ├── wechaty-grpc@1.3.0
  │ └── wechaty-puppet@1.18.3 deduped
  └── wechaty-puppet@1.18.3 deduped

@huan
Copy link
Member

huan commented Mar 29, 2022 •
edited

│ ├── wechaty-grpc@1.3.0

I have no idea why your node_modules has wechaty-grpc@1.3.0, which is not correct.

Could you please try to install wechaty-grpc@1.1 and see if it can solve your problem?

npm install wechaty-grpc@1.1

huan added a commit to wechaty/grpc that referenced this issue Mar 29, 2022
@huan
roll back handle -> weixi (wechaty/getting-started#254)
797ddbc
@huan huan mentioned this issue Mar 29, 2022
Open
@RustChater
Copy link
Author

after install wechaty-grcp@1.1:

wechaty-getting-started@1.18.4 /root/wechaty/getting-started
├─┬ wechaty-cqrs@0.7.5
│ ├─┬ wechaty-redux@1.19.7
│ │ ├── wechaty-puppet@1.18.3 deduped
│ │ └── wechaty@1.18.1 deduped
│ └── wechaty@1.18.1 deduped
├── wechaty-grpc@1.1.1
├─┬ wechaty-puppet-mock@1.18.2
│ └── wechaty-puppet@1.18.3
├─┬ wechaty-puppet-oicq@1.10.2
│ └── wechaty-puppet@1.18.3 deduped
├─┬ wechaty-puppet-walnut@1.11.8
│ └── wechaty-puppet@1.18.3 deduped
├─┬ wechaty-puppet-wechat@1.18.1
│ └── wechaty-puppet@1.18.3 deduped
├─┬ wechaty-puppet-wechat4u@1.11.1
│ └── wechaty-puppet@1.18.3 deduped
├─┬ wechaty-puppet-whatsapp@1.11.77
│ └── wechaty-puppet@0.41.9
├─┬ wechaty-puppet-xp@1.10.20
│ └── wechaty-puppet@1.18.3 deduped
└─┬ wechaty@1.18.1
  ├─┬ wechaty-puppet-service@1.18.2
  │ ├── wechaty-grpc@1.1.1 deduped
  │ └── wechaty-puppet@1.18.3 deduped
  └── wechaty-puppet@1.18.3 deduped

npm start

WECHATY_LOG=verbose \
WECHATY_PUPPET=wechaty-puppet-service \
WECHATY_PUPPET_SERVICE_TOKEN=insecure_xxxxxxxxx \
WECHATY_PUPPET_SERVICE_NO_TLS_INSECURE_CLIENT=false \
GRPC_VERBOSITY=DEBUG GRPC_TRACE=all \
npm start

> wechaty-getting-started@1.18.4 start
> cross-env NODE_OPTIONS="--no-warnings --loader=ts-node/esm" node examples/ding-dong-bot.ts

06:01:50 INFO Config registering process.on("unhandledRejection") for development/debug
06:01:50 VERB Config constructor()
06:01:50 VERB PoolifyMixin poolifyMixin(EventEmitter)
06:01:50 VERB WechatifyMixin wechatifyMixin(AbstractPoolifyMixin)
06:01:50 VERB ValidationMixin validationMixin(ContactMixin)
06:01:50 VERB ValidationMixin validationMixin(ContactImplBase)
06:01:50 VERB PoolifyMixin poolifyMixin(ContactImpl)
06:01:50 VERB ValidationMixin validationMixin(ContactSelfMixin)
06:01:50 VERB WechatifyMixin wechatifyMixin(EmptyBase)
06:01:50 VERB ValidationMixin validationMixin(FavoriteMixin)
06:01:50 VERB WechatifyMixin wechatifyMixin(EventEmitter)
06:01:50 VERB ValidationMixin validationMixin(FriendshipMixin)
06:01:50 VERB WechatifyMixin wechatifyMixin(EmptyBase)
06:01:50 VERB ValidationMixin validationMixin(ImageMixin)
06:01:50 VERB WechatifyMixin wechatifyMixin(EmptyBase)
06:01:50 VERB ValidationMixin validationMixin(LocationMixin)
06:01:50 VERB WechatifyMixin wechatifyMixin(EmptyBase)
06:01:50 VERB ValidationMixin validationMixin(PostMixin)
06:01:50 VERB WechatifyMixin wechatifyMixin(EventEmitter)
06:01:50 VERB ValidationMixin validationMixin(MessageMixin)
06:01:50 VERB ValidationMixin validationMixin(MessageImplBase)
06:01:50 VERB WechatifyMixin wechatifyMixin(EmptyBase)
06:01:50 VERB ValidationMixin validationMixin(MiniProgramMixin)
06:01:50 VERB WechatifyMixin wechatifyMixin(EmptyBase)
06:01:50 VERB ValidationMixin validationMixin(MomentMixin)
06:01:50 VERB WechatifyMixin wechatifyMixin(EmptyBase)
06:01:50 VERB ValidationMixin validationMixin(MoneyMixin)
06:01:50 VERB PoolifyMixin poolifyMixin(EventEmitter)
06:01:50 VERB WechatifyMixin wechatifyMixin(AbstractPoolifyMixin)
06:01:50 VERB ValidationMixin validationMixin(RoomMixin)
06:01:50 VERB WechatifyMixin wechatifyMixin(EmptyBase)
06:01:50 VERB ValidationMixin validationMixin(RoomInvitationMixin)
06:01:50 VERB WechatifyMixin wechatifyMixin(EmptyBase)
06:01:50 VERB PoolifyMixin poolifyMixin(AbstractWechatifyMixin)
06:01:50 VERB ValidationMixin validationMixin(TagMixin)
06:01:51 VERB WechatifyMixin wechatifyMixin(EmptyBase)
06:01:51 VERB ValidationMixin validationMixin(UrlLinkMixin)
06:01:51 VERB WechatifyMixin wechatifyMixin(EmptyBase)
06:01:51 VERB ValidationMixin validationMixin(DelayMixin)
06:01:51 VERB WechatyGErrorMixin gErrorMixin(WechatySkeleton)
06:01:51 VERB WechatifyUserModuleMixin wechatifyUserModuleMixin(GErrorMixin)
06:01:51 VERB WechatyIoMixin ioMixin(WechatifyUserModuleMixin)
06:01:51 VERB WechatyPuppetMixin puppetMixin(IoMixin)
06:01:51 VERB WechatyLoginMixin loginMixin(PuppetMixin)
06:01:51 VERB WechatyMiscMixin miscMixin(LoginMixin)
06:01:51 VERB WechatyPluginMixin pluginMixin(MiscMixin)
06:01:51 VERB ValidationMixin validationMixin(WechatyBase)
06:01:51 VERB ValidationMixin validationMixin(WechatyImplBase)
2022-03-29T06:01:51.772Z | index | Loading @grpc/grpc-js version 1.5.10
06:01:52 VERB wechaty-puppet-service monkeyPatchMetadataFromHttp2Headers()
06:01:52 VERB WechatyBuilder singleton()
06:01:52 VERB WechatyBuilder newInstance()
06:01:52 VERB WechatyLoginMixin constructor()
06:01:52 VERB WechatyPuppetMixin construct()
06:01:52 VERB WechatyIoMixin constructor()
06:01:52 VERB WechatifyUserModuleMixin constructor()
06:01:52 VERB WechatySkeleton constructor()
06:01:52 VERB StateSwitch constructor(WechatyReady, "{"log":{"enableTimestamp":true,"logLevel":4,"prefixFilter":{}}}")
06:01:52 VERB ServiceCtl<Wechaty> constructor()
06:01:52 VERB StateSwitch constructor(Wechaty, "{"log":{"enableTimestamp":true,"logLevel":4,"prefixFilter":{}}}")
06:01:52 VERB StateSwitch constructor(WechatyReset, "{"log":{"enableTimestamp":true,"logLevel":4,"prefixFilter":{}}}")
06:01:52 VERB Wechaty constructor()
06:01:52 VERB WechatySkeleton on(scan, listener) registering... listenerCount: 0
06:01:52 VERB WechatySkeleton on(login, listener) registering... listenerCount: 0
06:01:52 VERB WechatySkeleton on(logout, listener) registering... listenerCount: 0
06:01:52 VERB WechatySkeleton on(message, listener) registering... listenerCount: 0
06:01:52 VERB Wechaty start()
06:01:52 VERB WechatyLoginMixin init()
06:01:52 VERB WechatyPuppetMixin init()
06:01:52 VERB WechatifyUserModuleMixin init()
06:01:52 VERB WechatySkeleton init()
06:01:52 VERB Wechaty init() Raven disabled (import("raven") failed)
06:01:52 VERB WechatifyUserModuleMixin init() initializing Wechaty User Module (WUM) ...
06:01:52 VERB WechatifyMixin wechatifyUserModule(ContactImpl)
06:01:52 VERB WechatifyMixin wechatifyUserModule(ContactImpl)(Wechaty#xxxx-xxxx-xxxx-xxxx-xxxxxxxx<>(ding-dong-bot))
06:01:52 VERB WechatifyMixin wechatifyUserModule(ContactSelfImpl)
06:01:52 VERB WechatifyMixin wechatifyUserModule(ContactSelfImpl)(Wechaty#xxxx-xxxx-xxxx-xxxx-xxxxxxxx<>(ding-dong-bot))
06:01:52 VERB WechatifyMixin wechatifyUserModule(DelayImpl)
06:01:52 VERB WechatifyMixin wechatifyUserModule(DelayImpl)(Wechaty#xxxx-xxxx-xxxx-xxxx-xxxxxxxx<>(ding-dong-bot))
06:01:52 VERB WechatifyMixin wechatifyUserModule(FriendshipImpl)
06:01:52 VERB WechatifyMixin wechatifyUserModule(FriendshipImpl)(Wechaty#xxxx-xxxx-xxxx-xxxx-xxxxxxxx<>(ding-dong-bot))
06:01:52 VERB WechatifyMixin wechatifyUserModule(ImageImpl)
06:01:52 VERB WechatifyMixin wechatifyUserModule(ImageImpl)(Wechaty#xxxx-xxxx-xxxx-xxxx-xxxxxxxx<>(ding-dong-bot))
06:01:52 VERB WechatifyMixin wechatifyUserModule(LocationImpl)
06:01:52 VERB WechatifyMixin wechatifyUserModule(LocationImpl)(Wechaty#xxxx-xxxx-xxxx-xxxx-xxxxxxxx<>(ding-dong-bot))
06:01:52 VERB WechatifyMixin wechatifyUserModule(MessageImpl)
06:01:52 VERB WechatifyMixin wechatifyUserModule(MessageImpl)(Wechaty#xxxx-xxxx-xxxx-xxxx-xxxxxxxx<>(ding-dong-bot))
06:01:52 VERB WechatifyMixin wechatifyUserModule(MiniProgramImpl)
06:01:52 VERB WechatifyMixin wechatifyUserModule(MiniProgramImpl)(Wechaty#xxxx-xxxx-xxxx-xxxx-xxxxxxxx<>(ding-dong-bot))
06:01:52 VERB WechatifyMixin wechatifyUserModule(PostImpl)
06:01:52 VERB WechatifyMixin wechatifyUserModule(PostImpl)(Wechaty#xxxx-xxxx-xxxx-xxxx-xxxxxxxx<>(ding-dong-bot))
06:01:52 VERB WechatifyMixin wechatifyUserModule(RoomImpl)
06:01:52 VERB WechatifyMixin wechatifyUserModule(RoomImpl)(Wechaty#xxxx-xxxx-xxxx-xxxx-xxxxxxxx<>(ding-dong-bot))
06:01:52 VERB WechatifyMixin wechatifyUserModule(RoomInvitationImpl)
06:01:52 VERB WechatifyMixin wechatifyUserModule(RoomInvitationImpl)(Wechaty#xxxx-xxxx-xxxx-xxxx-xxxxxxxx<>(ding-dong-bot))
06:01:52 VERB WechatifyMixin wechatifyUserModule(TagImpl)
06:01:52 VERB WechatifyMixin wechatifyUserModule(TagImpl)(Wechaty#xxxx-xxxx-xxxx-xxxx-xxxxxxxx<>(ding-dong-bot))
06:01:52 VERB WechatifyMixin wechatifyUserModule(UrlLinkImpl)
06:01:52 VERB WechatifyMixin wechatifyUserModule(UrlLinkImpl)(Wechaty#xxxx-xxxx-xxxx-xxxx-xxxxxxxx<>(ding-dong-bot))
06:01:52 VERB WechatifyUserModuleMixin init() initializing Wechaty User Module (WUM) ... done
06:01:52 VERB WechatyPuppetMixin init() instanciating puppet instance ...
06:01:52 VERB Puppet resolvePuppet({puppet: wechaty-puppet-service, puppetOptions: {}})
06:01:52 VERB Puppet resolvePuppet() resolving name "wechaty-puppet-service" ...
06:01:52 VERB Puppet resolvePuppetName(wechaty-puppet-service)
06:01:52 VERB Puppet resolvePuppetName(wechaty-puppet-service): ESM resolved
06:01:52 VERB Puppet resolvePuppet() resolving name "wechaty-puppet-service" ... done
06:01:52 VERB Puppet resolvePuppet() instanciating puppet ...
06:01:52 VERB PuppetSkeleton constructor({})
06:01:52 VERB PuppetMemoryMixin constructor()
06:01:52 VERB PuppetLoginMixin constructor()
06:01:52 VERB PuppetCacheMixin constructor()
06:01:52 VERB PuppetCacheAgent constructor()
06:01:52 VERB PuppetContactMixin constructor()
06:01:52 VERB PuppetRoomMemberMixin constructor()
06:01:52 VERB PuppetRoomMixin constructor()
06:01:52 VERB PuppetFriendshipMixin constructor()
06:01:52 VERB PuppetTagMixin constructor()
06:01:52 VERB PuppetRoomInvitationMixin constructor()
06:01:52 VERB PuppetMessageMixin constructor()
06:01:52 VERB PuppetMiscMixin constructor()
06:01:52 VERB ServiceCtl<PuppetServiceMixin> constructor()
06:01:52 VERB StateSwitch constructor(PuppetServiceMixin, "{"log":{"enableTimestamp":true,"logLevel":4,"prefixFilter":{}}}")
06:01:52 VERB StateSwitch constructor(PuppetServiceMixinReset, "{"log":{"enableTimestamp":true,"logLevel":4,"prefixFilter":{}}}")
06:01:52 VERB PuppetServiceMixin constructor() #0
06:01:52 VERB PuppetWatchdogAgent constructor(xxxx-xxxx-xxxx-xxxx-xxxxxxxx)
06:01:52 VERB PuppetWatchdogAgent constructor() timeout 60 seconds
06:01:52 VERB ReadyMixin constructor()
06:01:52 VERB PuppetPostMixin constructor()
06:01:52 VERB PuppetSayableMixin constructor()
06:01:52 VERB TapMixin constructor()
06:01:52 VERB Puppet constructor({})
06:01:52 VERB PayloadStore constructor({"token":"insecure_xxxxx_xxxx"})
06:01:52 VERB PuppetService hookPayloadStore()
06:01:52 VERB Puppet resolvePuppet() instanciating puppet ... done
06:01:52 VERB WechatyPuppetMixin init() instanciating puppet instance ... done
06:01:52 VERB WechatyPuppetMixin init() setting memory ...
06:01:52 VERB PuppetMemoryMixin setMemory(ding-dong-bot)
06:01:52 VERB WechatyPuppetMixin init() setting memory ... done
06:01:52 VERB WechatyPuppetMixin init() setting up events ...
06:01:52 VERB WechatyPuppetMixin __setupPuppetEvents(Puppet<PuppetService>(ding-dong-bot))
06:01:52 VERB PuppetMixin __setupPuppetEvents() puppet.on(friendship) (listenerCount:0) registering...
06:01:52 VERB PuppetMixin __setupPuppetEvents() puppet.on(login) (listenerCount:1) registering...
06:01:52 VERB PuppetMixin __setupPuppetEvents() puppet.on(logout) (listenerCount:1) registering...
06:01:52 VERB PuppetMixin __setupPuppetEvents() puppet.on(message) (listenerCount:0) registering...
06:01:52 VERB PuppetMixin __setupPuppetEvents() puppet.on(post) (listenerCount:0) registering...
06:01:52 VERB PuppetMixin __setupPuppetEvents() puppet.on(room-invite) (listenerCount:0) registering...
06:01:52 VERB PuppetMixin __setupPuppetEvents() puppet.on(room-join) (listenerCount:0) registering...
06:01:52 VERB PuppetMixin __setupPuppetEvents() puppet.on(room-leave) (listenerCount:0) registering...
06:01:52 VERB PuppetMixin __setupPuppetEvents() puppet.on(room-topic) (listenerCount:0) registering...
06:01:52 VERB PuppetMixin __setupPuppetEvents() puppet.on(scan) (listenerCount:0) registering...
06:01:52 VERB PuppetMixin __setupPuppetEvents() puppet.on(dirty) (listenerCount:0) registering...
06:01:52 VERB PuppetMixin __setupPuppetEvents() puppet.on(dong) (listenerCount:0) registering...
06:01:52 VERB PuppetMixin __setupPuppetEvents() puppet.on(error) (listenerCount:0) registering...
06:01:52 VERB PuppetMixin __setupPuppetEvents() puppet.on(heartbeat) (listenerCount:0) registering...
06:01:52 VERB PuppetMixin __setupPuppetEvents() puppet.on(ready) (listenerCount:0) registering...
06:01:52 VERB PuppetMixin __setupPuppetEvents() puppet.on(reset) (listenerCount:0) registering...
06:01:52 VERB WechatyPuppetMixin __setupPuppetEvents() ... done
06:01:52 VERB WechatyPuppetMixin init() setting up events ... done
06:01:52 VERB WechatyPuppetMixin init() emitting "puppet" event ...
06:01:52 VERB WechatyPuppetMixin init() emitting "puppet" event ... done
06:01:52 VERB ServiceCtl<Wechaty> start()
06:01:52 VERB StateSwitch <Wechaty> active(pending) <- (false)
06:01:52 VERB ServiceCtl<Wechaty> start() super.start() ...
06:01:52 VERB WechatyPuppetMixin start()
06:01:52 VERB WechatyPuppetMixin start() super.start() ...
06:01:52 VERB WechatyIoMixin start()
06:01:52 VERB WechatySkeleton start()
06:01:52 VERB WechatyLoginMixin init()
06:01:52 VERB WechatyPuppetMixin init()
06:01:52 VERB WechatifyUserModuleMixin init()
06:01:52 VERB WechatySkeleton init()
06:01:52 VERB WechatifyUserModuleMixin init() Wechaty User Module (WUM)s have already wechatified: skip
06:01:52 VERB WechatyPuppetMixin init() skipped because this puppet has already been inited before.
06:01:52 VERB WechatyPuppetMixin start() super.start() ... done
06:01:52 VERB WechatyPuppetMixin start() starting puppet ...
06:01:52 VERB ReadyMixin start()
06:01:52 VERB PuppetServiceMixin start()
06:01:52 VERB ServiceCtl<PuppetServiceMixin> start()
06:01:52 VERB StateSwitch <PuppetServiceMixin> active(pending) <- (false)
06:01:52 VERB ServiceCtl<PuppetServiceMixin> start() super.start() ...
06:01:52 VERB PuppetCacheMixin start()
06:01:52 VERB PuppetLoginMixin start()
06:01:52 VERB PuppetMemoryMixin start()
06:01:52 VERB PuppetSkeleton start()
06:01:52 VERB PuppetCacheAgent start()
06:01:52 VERB PuppetCacheMixin start() "dirty" event listener added
06:01:52 VERB ServiceCtl<PuppetServiceMixin> start() super.start() ... done
06:01:52 VERB ServiceCtl<PuppetServiceMixin> start() this.onStart() ...
06:01:52 VERB PuppetService onStart()
06:01:52 VERB PuppetService start() instanciating GrpcManager ...
06:01:52 VERB GrpcManager constructor({})
06:01:52 VERB GrpcManager constructor() tlsRootCert(hash): "xxxxxxxxxxxxxxxxxxxxxxxxxxxx"
06:01:52 VERB GrpcManager constructor() token: "insecure_xxxxx_xxxx"
06:01:52 VERB GrpcManager constructor() endpoint: "wechaty://api.chatie.io/insecure_xxxxx_xxxx"
06:01:52 VERB GrpcManager constructor() disableTls: "false"
06:01:52 VERB GrpcManager constructor() serverName(SNI): "insecure"
06:01:52 VERB PuppetService start() instanciating GrpcManager ... done
06:01:52 VERB PuppetService start() setting up bridge grpc event stream ...
06:01:52 VERB PuppetService bridgeGrpcEventStream(client)
06:01:52 VERB PuppetService start() setting up bridge grpc event stream ... done
06:01:52 VERB PuppetService start() starting grpc manager...
06:01:52 VERB GrpcManager start()
06:01:52 VERB GrpcManager start() initializing client ...
06:01:52 VERB GrpcManager initClient()
06:01:52 VERB GrpcManager initClient() TLS: enabled
2022-03-29T06:01:52.434Z | resolving_load_balancer | wechaty://api.chatie.io/insecure_xxxxx_xxxx IDLE -> IDLE
2022-03-29T06:01:52.434Z | connectivity_state | (1) wechaty://api.chatie.io/insecure_xxxxx_xxxx IDLE -> IDLE
2022-03-29T06:01:52.436Z | channel | (1) wechaty://api.chatie.io/insecure_xxxxx_xxxx Channel constructed with options {
  "grpc.ssl_target_name_override": "insecure",
  "grpc.default_authority": "insecure_xxxxx_xxxx"
}
2022-03-29T06:01:52.533Z | channel_stacktrace | (1) Channel constructed
    at new ChannelImplementation (/root/wechaty/getting-started/node_modules/@grpc/grpc-js/src/channel.ts:338:19)
    at new Client (/root/wechaty/getting-started/node_modules/@grpc/grpc-js/src/client.ts:153:30)
    at new ServiceClientImpl (/root/wechaty/getting-started/node_modules/@grpc/grpc-js/src/make-client.ts:128:3)
    at GrpcManager.initClient (file:///root/wechaty/getting-started/node_modules/wechaty-puppet-service/src/client/grpc-manager.ts:258:20)
    at GrpcManager.start (file:///root/wechaty/getting-started/node_modules/wechaty-puppet-service/src/client/grpc-manager.ts:153:16)
    at PuppetService.onStart (file:///root/wechaty/getting-started/node_modules/wechaty-puppet-service/src/client/puppet-service.ts:173:23)
    at PuppetService.start (file:///root/wechaty/getting-started/node_modules/state-switch/src/service-ctl/service-ctl.ts:89:20)
    at async PuppetService.start (file:///root/wechaty/getting-started/node_modules/wechaty-puppet/src/mixins/service-mixin.ts:34:7)
    at async PuppetService.start (file:///root/wechaty/getting-started/node_modules/wechaty-puppet/src/mixins/ready-mixin.ts:24:7)
    at async WechatyImpl.start (file:///root/wechaty/getting-started/node_modules/wechaty/src/wechaty-mixins/puppet-mixin.ts:83:11)
06:01:52 VERB GrpcManager initClient() ... done
06:01:52 VERB GrpcManager start() initializing client ... done
06:01:52 VERB GrpcManager start() starting stream ...
06:01:52 VERB GrpcManager startStream()
06:01:52 VERB GrpcManager startStream() grpc -> event() ...
2022-03-29T06:01:52.536Z | channel | (1) wechaty://api.chatie.io/insecure_xxxxx_xxxx createCall [0] method="/wechaty.Puppet/Event", deadline=Infinity
2022-03-29T06:01:52.538Z | call_stream | [0] Sending metadata
2022-03-29T06:01:52.559Z | resolving_load_balancer | wechaty://api.chatie.io/insecure_xxxxx_xxxx IDLE -> CONNECTING
2022-03-29T06:01:52.559Z | connectivity_state | (1) wechaty://api.chatie.io/insecure_xxxxx_xxxx IDLE -> CONNECTING
2022-03-29T06:01:52.560Z | resolving_load_balancer | wechaty://api.chatie.io/insecure_xxxxx_xxxx CONNECTING -> CONNECTING
2022-03-29T06:01:52.560Z | connectivity_state | (1) wechaty://api.chatie.io/insecure_xxxxx_xxxx CONNECTING -> CONNECTING
2022-03-29T06:01:52.560Z | channel | (1) wechaty://api.chatie.io/insecure_xxxxx_xxxx callRefTimer.ref | configSelectionQueue.length=1 pickQueue.length=0
2022-03-29T06:01:52.561Z | call_stream | [0] write() called with message of length 0
2022-03-29T06:01:52.562Z | call_stream | [0] end() called
06:01:52 VERB GrpcManager startStream() grpc -> event() ... done
06:01:52 VERB GrpcManager startStream() grpc -> event peeking data or timeout ...
2022-03-29T06:01:52.563Z | call_stream | [0] deferring writing data chunk of length 5
2022-03-29T06:01:53.588Z | pick_first | Connect to address list IP.IP.IP.IP:8788
2022-03-29T06:01:53.590Z | subchannel | (2) IP.IP.IP.IP:8788 Subchannel constructed with options {
  "grpc.ssl_target_name_override": "insecure",
  "grpc.default_authority": "insecure_xxxxx_xxxx"
}
2022-03-29T06:01:53.590Z | subchannel_refcount | (2) IP.IP.IP.IP:8788 refcount 0 -> 1
2022-03-29T06:01:53.590Z | subchannel_refcount | (2) IP.IP.IP.IP:8788 refcount 1 -> 2
2022-03-29T06:01:53.591Z | pick_first | Start connecting to subchannel with address IP.IP.IP.IP:8788
2022-03-29T06:01:53.591Z | pick_first | IDLE -> CONNECTING
2022-03-29T06:01:53.592Z | resolving_load_balancer | wechaty://api.chatie.io/insecure_xxxxx_xxxx CONNECTING -> CONNECTING
2022-03-29T06:01:53.592Z | channel | (1) wechaty://api.chatie.io/insecure_xxxxx_xxxx callRefTimer.unref | configSelectionQueue.length=1 pickQueue.length=0
2022-03-29T06:01:53.592Z | connectivity_state | (1) wechaty://api.chatie.io/insecure_xxxxx_xxxx CONNECTING -> CONNECTING
2022-03-29T06:01:53.592Z | subchannel | (2) IP.IP.IP.IP:8788 IDLE -> CONNECTING
2022-03-29T06:01:53.593Z | pick_first | CONNECTING -> CONNECTING
2022-03-29T06:01:53.593Z | resolving_load_balancer | wechaty://api.chatie.io/insecure_xxxxx_xxxx CONNECTING -> CONNECTING
2022-03-29T06:01:53.593Z | connectivity_state | (1) wechaty://api.chatie.io/insecure_xxxxx_xxxx CONNECTING -> CONNECTING
2022-03-29T06:01:53.594Z | channel | (1) wechaty://api.chatie.io/insecure_xxxxx_xxxx Pick result for call [0]: QUEUE subchannel: null status: undefined undefined
2022-03-29T06:01:53.594Z | channel | (1) wechaty://api.chatie.io/insecure_xxxxx_xxxx callRefTimer.ref | configSelectionQueue.length=0 pickQueue.length=1
2022-03-29T06:01:53.595Z | subchannel | (2) IP.IP.IP.IP:8788 creating HTTP/2 session
2022-03-29T06:01:53.605Z | subchannel | (2) IP.IP.IP.IP:8788 connection closed with error 140034959882176:error:1408F10B:SSL routines:ssl3_get_record:wrong version number:../deps/openssl/openssl/ssl/record/ssl3_record.c:332:

2022-03-29T06:01:53.605Z | subchannel | (2) IP.IP.IP.IP:8788 connection closed
2022-03-29T06:01:53.606Z | subchannel | (2) IP.IP.IP.IP:8788 CONNECTING -> TRANSIENT_FAILURE
2022-03-29T06:01:53.607Z | pick_first | CONNECTING -> TRANSIENT_FAILURE
2022-03-29T06:01:53.607Z | resolving_load_balancer | wechaty://api.chatie.io/insecure_xxxxx_xxxx CONNECTING -> TRANSIENT_FAILURE
2022-03-29T06:01:53.607Z | channel | (1) wechaty://api.chatie.io/insecure_xxxxx_xxxx callRefTimer.unref | configSelectionQueue.length=0 pickQueue.length=0
2022-03-29T06:01:53.608Z | channel | (1) wechaty://api.chatie.io/insecure_xxxxx_xxxx Pick result for call [0]: TRANSIENT_FAILURE subchannel: null status: 14 No connection established
2022-03-29T06:01:53.609Z | call_stream | [0] cancelWithStatus code: 14 details: "No connection established"
2022-03-29T06:01:53.609Z | call_stream | [0] ended with status: code=14 details="No connection established"
2022-03-29T06:01:53.609Z | connectivity_state | (1) wechaty://api.chatie.io/insecure_xxxxx_xxxx CONNECTING -> TRANSIENT_FAILURE
06:01:53 VERB GrpcManager startStream() grpc -> event peeking data or timeout ... timeout
06:01:53 VERB GrpcManager startStream() grpc -> event peeking data or timeout ... data peeked
06:01:53 VERB GrpcManager startStream() initializing event stream ...
06:01:53 VERB GrpcManager startStream() initializing event stream ... done
06:01:53 VERB GrpcManager startStream() ... done
06:01:53 VERB GrpcManager start() starting stream ... done
06:01:53 VERB GrpcManager start() calling grpc server: start() ...
2022-03-29T06:01:53.612Z | channel | (1) wechaty://api.chatie.io/insecure_xxxxx_xxxx createCall [1] method="/wechaty.Puppet/Start", deadline=Infinity
2022-03-29T06:01:53.613Z | call_stream | [1] Sending metadata
2022-03-29T06:01:53.613Z | channel | (1) wechaty://api.chatie.io/insecure_xxxxx_xxxx Pick result for call [1]: TRANSIENT_FAILURE subchannel: null status: 14 No connection established
2022-03-29T06:01:53.613Z | call_stream | [1] cancelWithStatus code: 14 details: "No connection established"
2022-03-29T06:01:53.614Z | call_stream | [1] ended with status: code=14 details="No connection established"
2022-03-29T06:01:53.614Z | call_stream | [1] write() called with message of length 0
2022-03-29T06:01:53.615Z | call_stream | [1] end() called
2022-03-29T06:01:53.615Z | call_stream | [1] deferring writing data chunk of length 5
06:01:53 ERR StarterBot Error: 14 UNAVAILABLE: No connection established
2022-03-29T06:01:54.593Z | subchannel | (2) IP.IP.IP.IP:8788 TRANSIENT_FAILURE -> IDLE
2022-03-29T06:01:54.594Z | subchannel_refcount | (2) IP.IP.IP.IP:8788 refcount 2 -> 1
2022-03-29T06:01:54.594Z | pick_first | TRANSIENT_FAILURE -> IDLE
2022-03-29T06:01:54.594Z | resolving_load_balancer | wechaty://api.chatie.io/insecure_xxxxx_xxxx TRANSIENT_FAILURE -> IDLE
2022-03-29T06:01:54.594Z | connectivity_state | (1) wechaty://api.chatie.io/insecure_xxxxx_xxxx TRANSIENT_FAILURE -> IDLE

@huan huan added the bug label Mar 29, 2022
@huan
Copy link
Member

huan commented Mar 29, 2022 •
edited

After the investigation, we discovered that this is a bug and should have been fixed via

With the above changes, the system should work as expected after running:

rm -fr node_modules package-lock.json
npm install

Please try to use the latest wechaty-grpc and try again to see if it solves all your problems:

npm install wechaty-grpc@1.5.2

Let me know your result after the update, thank you very much!

@RustChater
Copy link
Author

RustChater commented Mar 29, 2022 •
edited

Exciting! it works.
follow your tips, run

rm -fr node_modules package-lock.json
npm install
npm install wechaty-grpc@1.5.2

WECHATY_LOG=verbose \
WECHATY_PUPPET=wechaty-puppet-service \
WECHATY_PUPPET_SERVICE_TOKEN=insecure_xxxxxx \
WECHATY_PUPPET_SERVICE_NO_TLS_INSECURE_CLIENT=true \
npm start

ding-dong is working on Wechat, thanks! :)

@huan
Copy link
Member

huan commented Mar 29, 2022

Great to know that, you are welcome!

And your issue is very valuable for solving this problem, appreciate it!

@huan huan closed this as completed Mar 29, 2022
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
bug
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@huan @RustChater