wechaty/puppet-service

TLS & SNI Problem: cannot connect to Puppet Server after Wechaty 1.0 migiration

hcfw007 opened this issue · 18 comments

hcfw007 commented

Recently we are testing our puppet with wechaty 1.0. The puppet-side migration went well, now it's running wechaty-io-client with wechaty@1.10.4 and wechaty-puppet@1.10.2.
However when I try to connect the puppet using a bot with wechaty-puppet-service@1.10.2 (which comes with wechaty@1.10.4), it always throw a No connection established error. The server side should be fine since the server started log did show up:

11:10:38 VERB PuppetServer start() initializing authorization with token ... done
11:10:38 VERB PuppetServer start() initializing gRPC health service ...
11:10:38 VERB PuppetServer start() initializing gRPC health service ... done
11:10:38 VERB PuppetServer start() initializing TLS CA ...
11:10:38 VERB PuppetServer start() initializing TLS CA ... done
11:10:38 VERB PuppetServer start() initializing gRPC server credentials ...
11:10:38 VERB PuppetServer start() TLS enabled.
11:10:38 VERB PuppetServer start() initializing gRPC server credentials ... done
11:10:38 VERB PuppetServer start() gRPC server starting ...
11:10:38 VERB PuppetServer start() gRPC server starting ... done
11:10:38 SILL StateSwitch <IoClient> active() is pending
11:10:38 VERB StateSwitch <IoClient> active(true) <- (pending)

Here's the error from client:

10:55:18 VERB PuppetService start() instanciating GrpcManager ... done
10:55:18 VERB PuppetService start() setting up bridge grpc event stream ...
10:55:18 VERB PuppetService bridgeGrpcEventStream(client)
10:55:18 VERB PuppetService start() setting up bridge grpc event stream ... done
10:55:18 VERB PuppetService start() starting grpc manager...
10:55:18 VERB GrpcManager start()
10:55:18 VERB GrpcManager start() initializing client ...
10:55:18 VERB GrpcManager initClient()
10:55:18 VERB GrpcManager initClient() TLS: enabled
10:55:18 VERB GrpcManager initClient() ... done
10:55:18 VERB GrpcManager start() initializing client ... done
10:55:18 VERB GrpcManager start() starting stream ...
10:55:18 VERB GrpcManager startStream()
10:55:18 VERB GrpcManager startStream() grpc -> event() ...
10:55:19 VERB GrpcManager startStream() grpc -> event() ... done
10:55:19 VERB GrpcManager startStream() grpc -> event peeking data or timeout ...
10:55:20 VERB GrpcManager startStream() grpc -> event peeking data or timeout ... timeout
10:55:20 VERB GrpcManager startStream() grpc -> event peeking data or timeout ... data peeked
10:55:20 VERB GrpcManager startStream() initializing event stream ...
10:55:20 VERB GrpcManager startStream() initializing event stream ... done
10:55:20 VERB GrpcManager startStream() ... done
10:55:20 VERB GrpcManager start() starting stream ... done
10:55:20 VERB GrpcManager start() calling grpc server: start() ...
10:55:20 ERR Config ###########################
10:55:20 ERR Config Wechaty unhandledRejection: GError: from(`object`): {"gerror":"{\"code\":14,\"details\":\"No connection established\",\"message\":\"14 UNAVAILABLE: No connection established\",\"name\":\"Error\",\"stack\":\"Error: 14 UNAVAILABLE: No connection established\\n    at Object.callErrorFromStatus (/Users/myonlystarcn/LocalDocuments/code/work/wechaty-1.0/wxwork-test/node_modules/@grpc/grpc-js/src/call.ts:81:24)\\n    at Object.onReceiveStatus (/Users/myonlystarcn/LocalDocuments/code/work/wechaty-1.0/wxwork-test/node_modules/@grpc/grpc-js/src/client.ts:343:36)\\n    at Object.onReceiveStatus (/Users/myonlystarcn/LocalDocuments/code/work/wechaty-1.0/wxwork-test/node_modules/@grpc/grpc-js/src/client-interceptors.ts:462:34)\\n    at Object.onReceiveStatus (/Users/myonlystarcn/LocalDocuments/code/work/wechaty-1.0/wxwork-test/node_modules/@grpc/grpc-js/src/client-interceptors.ts:424:48)\\n    at /Users/myonlystarcn/LocalDocuments/code/work/wechaty-1.0/wxwork-test/node_modules/@grpc/grpc-js/src/call-stream.ts:323:24\\n    at processTicksAndRejections (node:internal/process/task_queues:78:11)\"}"}
    at Function.from (/Users/myonlystarcn/LocalDocuments/code/work/wechaty-1.0/wxwork-test/node_modules/gerror/src/gerror/gerror.ts:87:15)
    at PuppetService.<anonymous> (/Users/myonlystarcn/LocalDocuments/code/work/wechaty-1.0/wxwork-test/node_modules/wechaty/src/wechaty-mixins/puppet-mixin.ts:203:41)
    at PuppetService.emit (node:events:390:28)
    at PuppetService.emit (node:domain:475:12)
    at PuppetService.emit (/Users/myonlystarcn/LocalDocuments/code/work/wechaty-1.0/wxwork-test/node_modules/wechaty-puppet/src/puppet/puppet-skeleton.ts:137:18)
    at PuppetService.start (/Users/myonlystarcn/LocalDocuments/code/work/wechaty-1.0/wxwork-test/node_modules/state-switch/src/service-ctl/service-ctl.ts:98:14)
    at processTicksAndRejections (node:internal/process/task_queues:96:5)
    at async PuppetService.start (/Users/myonlystarcn/LocalDocuments/code/work/wechaty-1.0/wxwork-test/node_modules/wechaty-puppet/src/mixins/service-mixin.ts:34:7)
    at async WechatyImpl.start (/Users/myonlystarcn/LocalDocuments/code/work/wechaty-1.0/wxwork-test/node_modules/wechaty/src/wechaty-mixins/puppet-mixin.ts:81:11)
    at async WechatyImpl.start (/Users/myonlystarcn/LocalDocuments/code/work/wechaty-1.0/wxwork-test/node_modules/wechaty/src/wechaty-mixins/login-mixin.ts:114:7) [object Promise]
10:55:20 ERR Config ###########################
huan commented

Could you please try the next version of wechaty and post your minimum reproducible code with steps?

hcfw007 commented

Sure thing.
package.json:

...
"wechaty": "^1.11.33",
"wechaty-puppet-mock": "^1.10.2",
"wechaty-puppet-service": "^1.11.2"

example code:

import { WechatyBuilder } from 'wechaty'
import PuppetMock from 'wechaty-puppet-mock'
import { PuppetServer, PuppetServerOptions} from 'wechaty-puppet-service'

async function main() {
  const host = '0.0.0.0'
  const port = '8788'

  const serverOptions = {
    endpoint: `${host}:${port}`,
    puppet: new PuppetMock(),
    token: 'puppet_test_whatsoever'
  } as PuppetServerOptions

  const puppetServer = new PuppetServer(serverOptions)

  await puppetServer.start()

  const bot = WechatyBuilder.build({
    puppet: 'wechaty-puppet-service',
    puppetOptions: {
      endpoint: `${host}:${port}`,
      token: 'puppet_test_whatsoever',
    }
  })

  bot.start()

  await new Promise(resolve => {
    setTimeout(resolve, 3600)
  })
}
main()
hcfw007 commented

full log:

13:37:47 SILL Puppet Config: WECHATY_LOG set level to silly
13:37:47 INFO Config registering process.on("unhandledRejection") for development/debug
13:37:47 VERB Config constructor()
13:37:47 VERB PoolifyMixin poolifyMixin(EventEmitter)
13:37:47 VERB WechatifyMixin wechatifyMixin(AbstractPoolifyMixin)
13:37:47 VERB ValidationMixin validationMixin(ContactMixin)
13:37:47 VERB ValidationMixin validationMixin(ContactImplBase)
13:37:47 VERB PoolifyMixin poolifyMixin(ContactImpl)
13:37:47 VERB ValidationMixin validationMixin(ContactSelfMixin)
13:37:47 VERB WechatifyMixin wechatifyMixin(EmptyBase)
13:37:47 VERB ValidationMixin validationMixin(FavoriteMixin)
13:37:47 VERB WechatifyMixin wechatifyMixin(EventEmitter)
13:37:47 VERB ValidationMixin validationMixin(FriendshipMixin)
13:37:47 VERB WechatifyMixin wechatifyMixin(EmptyBase)
13:37:47 VERB ValidationMixin validationMixin(ImageMixin)
13:37:47 VERB WechatifyMixin wechatifyMixin(EmptyBase)
13:37:47 VERB ValidationMixin validationMixin(LocationMixin)
13:37:48 VERB WechatifyMixin wechatifyMixin(EmptyBase)
13:37:48 VERB ValidationMixin validationMixin(UrlLinkMixin)
13:37:48 VERB WechatifyMixin wechatifyMixin(EmptyBase)
13:37:48 VERB ValidationMixin validationMixin(MiniProgramMixin)
13:37:48 VERB WechatifyMixin wechatifyMixin(EventEmitter)
13:37:48 VERB ValidationMixin validationMixin(MessageMixin)
13:37:48 VERB ValidationMixin validationMixin(MessageImplBase)
13:37:48 VERB WechatifyMixin wechatifyMixin(EmptyBase)
13:37:48 VERB ValidationMixin validationMixin(MomentMixin)
13:37:48 VERB WechatifyMixin wechatifyMixin(EmptyBase)
13:37:48 VERB ValidationMixin validationMixin(MoneyMixin)
13:37:48 VERB PoolifyMixin poolifyMixin(EventEmitter)
13:37:48 VERB WechatifyMixin wechatifyMixin(AbstractPoolifyMixin)
13:37:48 VERB ValidationMixin validationMixin(RoomMixin)
13:37:48 VERB WechatifyMixin wechatifyMixin(EmptyBase)
13:37:48 VERB ValidationMixin validationMixin(RoomInvitationMixin)
13:37:48 VERB WechatifyMixin wechatifyMixin(EmptyBase)
13:37:48 VERB PoolifyMixin poolifyMixin(AbstractWechatifyMixin)
13:37:48 VERB ValidationMixin validationMixin(TagMixin)
13:37:48 VERB WechatifyMixin wechatifyMixin(EmptyBase)
13:37:48 VERB ValidationMixin validationMixin(DelayMixin)
13:37:48 VERB WechatyGErrorMixin gErrorMixin(WechatySkeleton)
13:37:48 VERB WechatifyUserModuleMixin wechatifyUserModuleMixin(GErrorMixin)
13:37:48 VERB WechatyIoMixin ioMixin(WechatifyUserModuleMixin)
13:37:48 VERB WechatyPluginMixin pluginMixin(ServiceCtlMixin)
13:37:48 VERB WechatyPuppetMixin puppetMixin(PluginMixin)
13:37:48 VERB WechatyLoginMixin loginMixin(PuppetMixin)
13:37:48 VERB WechatyMiscMixin miscMixin(LoginMixin)
13:37:48 VERB ValidationMixin validationMixin(WechatyBase)
13:37:48 VERB ValidationMixin validationMixin(WechatyImplBase)
13:37:48 VERB wechaty-puppet-service monkeyPatchMetadataFromHttp2Headers()
13:37:49 VERB PuppetSkeleton constructor({})
13:37:49 VERB PuppetMemoryMixin constructor()
13:37:49 VERB PuppetLoginMixin constructor()
13:37:49 VERB PuppetCacheMixin constructor()
13:37:49 VERB PuppetCacheAgent constructor()
13:37:49 VERB PuppetContactMixin constructor()
13:37:49 VERB PuppetRoomMemberMixin constructor()
13:37:49 VERB PuppetRoomMixin constructor()
13:37:49 VERB PuppetFriendshipMixin constructor()
13:37:49 VERB PuppetTagMixin constructor()
13:37:49 VERB PuppetRoomInvitationMixin constructor()
13:37:49 VERB PuppetMessageMixin constructor()
13:37:49 VERB PuppetMiscMixin constructor()
13:37:49 VERB ServiceCtl<PuppetServiceMixin> constructor()
13:37:49 VERB StateSwitch constructor(PuppetServiceMixin, "{"log":{"enableTimestamp":true,"logLevel":5,"prefixFilter":{}}}")
13:37:49 VERB StateSwitch constructor(PuppetServiceMixinReset, "{"log":{"enableTimestamp":true,"logLevel":5,"prefixFilter":{}}}")
13:37:49 VERB PuppetServiceMixin constructor() #0
13:37:49 VERB PuppetWatchdogAgent constructor(f669153c-e46a-4d93-9a79-d385c73dcfc9)
13:37:49 VERB PuppetWatchdogAgent constructor() timeout 60 seconds
13:37:49 VERB Puppet constructor({})
13:37:49 VERB PuppetMock constructor()
13:37:49 VERB PuppetMock constructor() creating the default mocker
13:37:49 VERB Mocker constructor()
13:37:49 VERB PuppetServer constructor({endpoint: "0.0.0.0:8788", puppet: "Puppet<PuppetMock>(NONAME)", token: "puppet_test_whatsoever"})
13:37:49 VERB PuppetServer start()
13:37:49 VERB PuppetServer start() initializing FileBox UUID URN Registry ...
13:37:49 VERB PuppetServer start() initializing FileBox UUID URN Registry ... done
13:37:49 VERB PuppetServer start() initializing gRPC Server with options "{}"
13:37:49 VERB PuppetServer start() initializing gRPC Server ... done
13:37:49 VERB PuppetServer start() initializing puppet implementation with FileBoxUuid...
13:37:49 VERB EventStreamManager constructor(Puppet<PuppetMock>(NONAME))
13:37:49 VERB PuppetServer start() initializing puppet implementation with FileBoxUuid... done
13:37:49 VERB PuppetServer start() initializing authorization with token ...
13:37:49 VERB wechaty-puppet-service authImplToken()
13:37:49 VERB wechaty-puppet-service auth/auth-impl-token.ts authWrapHandlerToken(puppet_test_whatsoever)(contactAlias)
13:37:49 VERB wechaty-puppet-service auth/auth-impl-token.ts authWrapHandlerToken(puppet_test_whatsoever)(contactAvatar)
13:37:49 VERB wechaty-puppet-service auth/auth-impl-token.ts authWrapHandlerToken(puppet_test_whatsoever)(contactCorporationRemark)
13:37:49 VERB wechaty-puppet-service auth/auth-impl-token.ts authWrapHandlerToken(puppet_test_whatsoever)(contactDescription)
13:37:49 VERB wechaty-puppet-service auth/auth-impl-token.ts authWrapHandlerToken(puppet_test_whatsoever)(contactList)
13:37:49 VERB wechaty-puppet-service auth/auth-impl-token.ts authWrapHandlerToken(puppet_test_whatsoever)(contactPayload)
13:37:49 VERB wechaty-puppet-service auth/auth-impl-token.ts authWrapHandlerToken(puppet_test_whatsoever)(contactPhone)
13:37:49 VERB wechaty-puppet-service auth/auth-impl-token.ts authWrapHandlerToken(puppet_test_whatsoever)(contactSelfName)
13:37:49 VERB wechaty-puppet-service auth/auth-impl-token.ts authWrapHandlerToken(puppet_test_whatsoever)(contactSelfQRCode)
13:37:49 VERB wechaty-puppet-service auth/auth-impl-token.ts authWrapHandlerToken(puppet_test_whatsoever)(contactSelfSignature)
13:37:49 VERB wechaty-puppet-service auth/auth-impl-token.ts authWrapHandlerToken(puppet_test_whatsoever)(ding)
13:37:49 VERB wechaty-puppet-service auth/auth-impl-token.ts authWrapHandlerToken(puppet_test_whatsoever)(dirtyPayload)
13:37:49 VERB wechaty-puppet-service auth/auth-impl-token.ts authWrapHandlerToken(puppet_test_whatsoever)(event)
13:37:49 VERB wechaty-puppet-service auth/auth-impl-token.ts authWrapHandlerToken(puppet_test_whatsoever)(friendshipAccept)
13:37:49 VERB wechaty-puppet-service auth/auth-impl-token.ts authWrapHandlerToken(puppet_test_whatsoever)(friendshipAdd)
13:37:49 VERB wechaty-puppet-service auth/auth-impl-token.ts authWrapHandlerToken(puppet_test_whatsoever)(friendshipPayload)
13:37:49 VERB wechaty-puppet-service auth/auth-impl-token.ts authWrapHandlerToken(puppet_test_whatsoever)(friendshipSearchPhone)
13:37:49 VERB wechaty-puppet-service auth/auth-impl-token.ts authWrapHandlerToken(puppet_test_whatsoever)(friendshipSearchWeixin)
13:37:49 VERB wechaty-puppet-service auth/auth-impl-token.ts authWrapHandlerToken(puppet_test_whatsoever)(logout)
13:37:49 VERB wechaty-puppet-service auth/auth-impl-token.ts authWrapHandlerToken(puppet_test_whatsoever)(messageContact)
13:37:49 VERB wechaty-puppet-service auth/auth-impl-token.ts authWrapHandlerToken(puppet_test_whatsoever)(messageFile)
13:37:49 VERB wechaty-puppet-service auth/auth-impl-token.ts authWrapHandlerToken(puppet_test_whatsoever)(messageFileStream)
13:37:49 VERB wechaty-puppet-service auth/auth-impl-token.ts authWrapHandlerToken(puppet_test_whatsoever)(messageForward)
13:37:49 VERB wechaty-puppet-service auth/auth-impl-token.ts authWrapHandlerToken(puppet_test_whatsoever)(messageImage)
13:37:49 VERB wechaty-puppet-service auth/auth-impl-token.ts authWrapHandlerToken(puppet_test_whatsoever)(messageImageStream)
13:37:49 VERB wechaty-puppet-service auth/auth-impl-token.ts authWrapHandlerToken(puppet_test_whatsoever)(messageLocation)
13:37:49 VERB wechaty-puppet-service auth/auth-impl-token.ts authWrapHandlerToken(puppet_test_whatsoever)(messageMiniProgram)
13:37:49 VERB wechaty-puppet-service auth/auth-impl-token.ts authWrapHandlerToken(puppet_test_whatsoever)(messagePayload)
13:37:49 VERB wechaty-puppet-service auth/auth-impl-token.ts authWrapHandlerToken(puppet_test_whatsoever)(messageRecall)
13:37:49 VERB wechaty-puppet-service auth/auth-impl-token.ts authWrapHandlerToken(puppet_test_whatsoever)(messageSendContact)
13:37:49 VERB wechaty-puppet-service auth/auth-impl-token.ts authWrapHandlerToken(puppet_test_whatsoever)(messageSendFile)
13:37:49 VERB wechaty-puppet-service auth/auth-impl-token.ts authWrapHandlerToken(puppet_test_whatsoever)(messageSendFileStream)
13:37:49 VERB wechaty-puppet-service auth/auth-impl-token.ts authWrapHandlerToken(puppet_test_whatsoever)(messageSendLocation)
13:37:49 VERB wechaty-puppet-service auth/auth-impl-token.ts authWrapHandlerToken(puppet_test_whatsoever)(messageSendMiniProgram)
13:37:49 VERB wechaty-puppet-service auth/auth-impl-token.ts authWrapHandlerToken(puppet_test_whatsoever)(messageSendText)
13:37:49 VERB wechaty-puppet-service auth/auth-impl-token.ts authWrapHandlerToken(puppet_test_whatsoever)(messageSendUrl)
13:37:49 VERB wechaty-puppet-service auth/auth-impl-token.ts authWrapHandlerToken(puppet_test_whatsoever)(messageUrl)
13:37:49 VERB wechaty-puppet-service auth/auth-impl-token.ts authWrapHandlerToken(puppet_test_whatsoever)(roomAdd)
13:37:49 VERB wechaty-puppet-service auth/auth-impl-token.ts authWrapHandlerToken(puppet_test_whatsoever)(roomAnnounce)
13:37:49 VERB wechaty-puppet-service auth/auth-impl-token.ts authWrapHandlerToken(puppet_test_whatsoever)(roomAvatar)
13:37:49 VERB wechaty-puppet-service auth/auth-impl-token.ts authWrapHandlerToken(puppet_test_whatsoever)(roomCreate)
13:37:49 VERB wechaty-puppet-service auth/auth-impl-token.ts authWrapHandlerToken(puppet_test_whatsoever)(roomDel)
13:37:49 VERB wechaty-puppet-service auth/auth-impl-token.ts authWrapHandlerToken(puppet_test_whatsoever)(roomInvitationAccept)
13:37:49 VERB wechaty-puppet-service auth/auth-impl-token.ts authWrapHandlerToken(puppet_test_whatsoever)(roomInvitationPayload)
13:37:49 VERB wechaty-puppet-service auth/auth-impl-token.ts authWrapHandlerToken(puppet_test_whatsoever)(roomList)
13:37:49 VERB wechaty-puppet-service auth/auth-impl-token.ts authWrapHandlerToken(puppet_test_whatsoever)(roomMemberList)
13:37:49 VERB wechaty-puppet-service auth/auth-impl-token.ts authWrapHandlerToken(puppet_test_whatsoever)(roomMemberPayload)
13:37:49 VERB wechaty-puppet-service auth/auth-impl-token.ts authWrapHandlerToken(puppet_test_whatsoever)(roomPayload)
13:37:49 VERB wechaty-puppet-service auth/auth-impl-token.ts authWrapHandlerToken(puppet_test_whatsoever)(roomQRCode)
13:37:49 VERB wechaty-puppet-service auth/auth-impl-token.ts authWrapHandlerToken(puppet_test_whatsoever)(roomQuit)
13:37:49 VERB wechaty-puppet-service auth/auth-impl-token.ts authWrapHandlerToken(puppet_test_whatsoever)(roomTopic)
13:37:49 VERB wechaty-puppet-service auth/auth-impl-token.ts authWrapHandlerToken(puppet_test_whatsoever)(start)
13:37:49 VERB wechaty-puppet-service auth/auth-impl-token.ts authWrapHandlerToken(puppet_test_whatsoever)(stop)
13:37:49 VERB wechaty-puppet-service auth/auth-impl-token.ts authWrapHandlerToken(puppet_test_whatsoever)(tagContactAdd)
13:37:49 VERB wechaty-puppet-service auth/auth-impl-token.ts authWrapHandlerToken(puppet_test_whatsoever)(tagContactDelete)
13:37:49 VERB wechaty-puppet-service auth/auth-impl-token.ts authWrapHandlerToken(puppet_test_whatsoever)(tagContactList)
13:37:49 VERB wechaty-puppet-service auth/auth-impl-token.ts authWrapHandlerToken(puppet_test_whatsoever)(tagContactRemove)
13:37:49 VERB wechaty-puppet-service auth/auth-impl-token.ts authWrapHandlerToken(puppet_test_whatsoever)(version)
13:37:49 VERB wechaty-puppet-service auth/auth-impl-token.ts authWrapHandlerToken(puppet_test_whatsoever)(download)
13:37:49 VERB wechaty-puppet-service auth/auth-impl-token.ts authWrapHandlerToken(puppet_test_whatsoever)(upload)
13:37:49 VERB PuppetServer start() initializing authorization with token ... done
13:37:49 VERB PuppetServer start() initializing gRPC health service ...
13:37:49 VERB PuppetServer start() initializing gRPC health service ... done
13:37:49 VERB PuppetServer start() initializing TLS CA ...
13:37:49 VERB PuppetServer start() initializing TLS CA ... done
13:37:49 VERB PuppetServer start() initializing gRPC server credentials ...
13:37:49 VERB PuppetServer start() TLS enabled.
13:37:49 VERB PuppetServer start() initializing gRPC server credentials ... done
13:37:49 VERB PuppetServer start() gRPC server starting ...
13:37:49 VERB Wechaty init() Raven disabled (import("raven") failed)
13:37:49 VERB PuppetServer start() gRPC server starting ... done
13:37:49 VERB WechatyBuilder singleton()
13:37:49 VERB WechatyBuilder newInstance()
13:37:49 VERB WechatyLoginMixin constructor()
13:37:49 VERB WechatyPuppetMixin construct()
13:37:49 VERB WechatyIoMixin constructor()
13:37:49 VERB WechatifyUserModuleMixin constructor()
13:37:49 VERB WechatySkeleton constructor()
13:37:49 VERB ServiceCtl<Wechaty> constructor()
13:37:49 VERB StateSwitch constructor(Wechaty, "{"log":{"enableTimestamp":true,"logLevel":5,"prefixFilter":{}}}")
13:37:49 VERB StateSwitch constructor(WechatyReset, "{"log":{"enableTimestamp":true,"logLevel":5,"prefixFilter":{}}}")
13:37:49 VERB StateSwitch constructor(WechatyReady, "{"log":{"enableTimestamp":true,"logLevel":5,"prefixFilter":{}}}")
13:37:49 VERB Wechaty constructor()
13:37:49 VERB WechatyLoginMixin start()
13:37:49 VERB WechatyPuppetMixin start()
13:37:49 VERB WechatyPuppetMixin start() super.start() ...
13:37:49 VERB WechatyPluginMixin start()
13:37:49 VERB ServiceCtl<Wechaty> start()
13:37:49 SILL StateSwitch <Wechaty> active() is false
13:37:49 SILL StateSwitch <Wechaty> inactive() is true
13:37:49 SILL StateSwitch <Wechaty> active() is false
13:37:49 VERB StateSwitch <Wechaty> active(pending) <- (false)
13:37:49 VERB ServiceCtl<Wechaty> start() super.start() ...
13:37:49 VERB WechatyIoMixin start()
13:37:49 VERB WechatifyUserModuleMixin start()
13:37:49 VERB WechatySkeleton start()
13:37:49 VERB WechatifyUserModuleMixin _wechatifyUserModules()
13:37:49 VERB WechatifyUserModuleMixin _wechatifyUserModules() initializing Wechaty User Module (WUM) ...
13:37:49 VERB WechatifyMixin wechatifyUserModule(ContactImpl)
13:37:49 VERB WechatifyMixin wechatifyUserModule(ContactImpl)(Wechaty#ca75dbb3-9115-42dc-a9b3-7adb7ca50f99<wechaty-puppet-service>())
13:37:49 VERB WechatifyMixin wechatifyUserModule(ContactSelfImpl)
13:37:49 VERB WechatifyMixin wechatifyUserModule(ContactSelfImpl)(Wechaty#ca75dbb3-9115-42dc-a9b3-7adb7ca50f99<wechaty-puppet-service>())
13:37:49 VERB WechatifyMixin wechatifyUserModule(DelayImpl)
13:37:49 VERB WechatifyMixin wechatifyUserModule(DelayImpl)(Wechaty#ca75dbb3-9115-42dc-a9b3-7adb7ca50f99<wechaty-puppet-service>())
13:37:49 VERB WechatifyMixin wechatifyUserModule(FriendshipImpl)
13:37:49 VERB WechatifyMixin wechatifyUserModule(FriendshipImpl)(Wechaty#ca75dbb3-9115-42dc-a9b3-7adb7ca50f99<wechaty-puppet-service>())
13:37:49 VERB WechatifyMixin wechatifyUserModule(ImageImpl)
13:37:49 VERB WechatifyMixin wechatifyUserModule(ImageImpl)(Wechaty#ca75dbb3-9115-42dc-a9b3-7adb7ca50f99<wechaty-puppet-service>())
13:37:49 VERB WechatifyMixin wechatifyUserModule(LocationImpl)
13:37:49 VERB WechatifyMixin wechatifyUserModule(LocationImpl)(Wechaty#ca75dbb3-9115-42dc-a9b3-7adb7ca50f99<wechaty-puppet-service>())
13:37:49 VERB WechatifyMixin wechatifyUserModule(MessageImpl)
13:37:49 VERB WechatifyMixin wechatifyUserModule(MessageImpl)(Wechaty#ca75dbb3-9115-42dc-a9b3-7adb7ca50f99<wechaty-puppet-service>())
13:37:49 VERB WechatifyMixin wechatifyUserModule(MiniProgramImpl)
13:37:49 VERB WechatifyMixin wechatifyUserModule(MiniProgramImpl)(Wechaty#ca75dbb3-9115-42dc-a9b3-7adb7ca50f99<wechaty-puppet-service>())
13:37:49 VERB WechatifyMixin wechatifyUserModule(RoomImpl)
13:37:49 VERB WechatifyMixin wechatifyUserModule(RoomImpl)(Wechaty#ca75dbb3-9115-42dc-a9b3-7adb7ca50f99<wechaty-puppet-service>())
13:37:49 VERB WechatifyMixin wechatifyUserModule(RoomInvitationImpl)
13:37:49 VERB WechatifyMixin wechatifyUserModule(RoomInvitationImpl)(Wechaty#ca75dbb3-9115-42dc-a9b3-7adb7ca50f99<wechaty-puppet-service>())
13:37:49 VERB WechatifyMixin wechatifyUserModule(TagImpl)
13:37:49 VERB WechatifyMixin wechatifyUserModule(TagImpl)(Wechaty#ca75dbb3-9115-42dc-a9b3-7adb7ca50f99<wechaty-puppet-service>())
13:37:49 VERB WechatifyMixin wechatifyUserModule(UrlLinkImpl)
13:37:49 VERB WechatifyMixin wechatifyUserModule(UrlLinkImpl)(Wechaty#ca75dbb3-9115-42dc-a9b3-7adb7ca50f99<wechaty-puppet-service>())
13:37:49 VERB WechatifyUserModuleMixin _wechatifyUserModules() initializing Wechaty User Module (WUM) ... done
13:37:49 VERB ServiceCtl<Wechaty> start() super.start() ... done
13:37:49 VERB ServiceCtl<Wechaty> start() this.onStart() ...
13:37:49 VERB Wechaty onStart()
13:37:49 VERB Wechaty <wechaty-puppet-service>() onStart() v1.11.33 is starting...
13:37:49 VERB Wechaty id: ca75dbb3-9115-42dc-a9b3-7adb7ca50f99
13:37:49 VERB Wechaty onStart() ... done
13:37:49 VERB ServiceCtl<Wechaty> start() this.onStart() ... done
13:37:49 SILL StateSwitch <Wechaty> active() is pending
13:37:49 VERB StateSwitch <Wechaty> active(true) <- (pending)
13:37:49 VERB ServiceCtl<Wechaty> start() ... done
13:37:49 VERB WechatyPluginMixin start() installing plugins(global/0, instance/0) ...
13:37:49 VERB WechatyPluginMixin __activePlugin() 
13:37:49 VERB WechatyPluginMixin start() installing plugins(global/0, instance/0) ... done
13:37:49 VERB WechatyPuppetMixin start() super.start() ... done
13:37:49 SILL StateSwitch <WechatyReady> active() is false
13:37:49 VERB WechatyPuppetMixin start() initializing puppet instance ...
13:37:49 VERB WechatyPuppetMixin __initPuppetInstance() wechaty-puppet-service
13:37:49 VERB WechatyPuppetMixin __initPuppetInstance() instanciating puppet instance ...
13:37:49 VERB Puppet resolvePuppet({puppet: wechaty-puppet-service, puppetOptions: {"endpoint":"0.0.0.0:8788","token":"puppet_test_whatsoever"}})
13:37:49 VERB Puppet resolvePuppet() resolving name "wechaty-puppet-service" ...
13:37:49 VERB Puppet resolvePuppetName(wechaty-puppet-service)
13:37:49 VERB Puppet resolvePuppetName(wechaty-puppet-service): ESM resolved
13:37:49 VERB Puppet resolvePuppet() resolving name "wechaty-puppet-service" ... done
13:37:49 VERB Puppet resolvePuppet() instanciating puppet ...
13:37:49 VERB PuppetSkeleton constructor({"endpoint":"0.0.0.0:8788","token":"puppet_test_whatsoever"})
13:37:49 VERB PuppetMemoryMixin constructor()
13:37:49 VERB PuppetLoginMixin constructor()
13:37:49 VERB PuppetCacheMixin constructor()
13:37:49 VERB PuppetCacheAgent constructor()
13:37:49 VERB PuppetContactMixin constructor()
13:37:49 VERB PuppetRoomMemberMixin constructor()
13:37:49 VERB PuppetRoomMixin constructor()
13:37:49 VERB PuppetFriendshipMixin constructor()
13:37:49 VERB PuppetTagMixin constructor()
13:37:49 VERB PuppetRoomInvitationMixin constructor()
13:37:49 VERB PuppetMessageMixin constructor()
13:37:49 VERB PuppetMiscMixin constructor()
13:37:49 VERB ServiceCtl<PuppetServiceMixin> constructor()
13:37:49 VERB StateSwitch constructor(PuppetServiceMixin, "{"log":{"enableTimestamp":true,"logLevel":5,"prefixFilter":{}}}")
13:37:49 VERB StateSwitch constructor(PuppetServiceMixinReset, "{"log":{"enableTimestamp":true,"logLevel":5,"prefixFilter":{}}}")
13:37:49 VERB PuppetServiceMixin constructor() #1
13:37:49 VERB PuppetWatchdogAgent constructor(4b8cbd4b-25ca-4229-9627-71d3e10a1d13)
13:37:49 VERB PuppetWatchdogAgent constructor() timeout 60 seconds
13:37:49 VERB Puppet constructor({"endpoint":"0.0.0.0:8788","token":"puppet_test_whatsoever"})
13:37:49 VERB PayloadStore constructor({"token":"puppet_test_whatsoever"})
13:37:49 SILL PayloadStore constructor() storeDir: "/Users/myonlystarcn/.wechaty/wechaty-puppet-service/puppet_test_whatsoever/v1.11"
13:37:49 VERB PuppetService hookPayloadStore()
13:37:49 VERB Puppet resolvePuppet() instanciating puppet ... done
13:37:49 VERB WechatyPuppetMixin __initPuppetInstance() instanciating puppet instance ... done
13:37:49 VERB WechatyPuppetMixin __initPuppetInstance() setting memory ...
13:37:49 VERB PuppetMemoryMixin setMemory(undefined)
13:37:49 VERB WechatyPuppetMixin __initPuppetInstance() setting memory ... done
13:37:49 VERB WechatyPuppetMixin __initPuppetInstance() setting up events ...
13:37:49 VERB WechatyPuppetMixin __setupPuppetEvents(Puppet<PuppetService>(NONAME))
13:37:49 VERB PuppetMixin __setupPuppetEvents() puppet.on(friendship) (listenerCount:0) registering...
13:37:49 VERB PuppetMixin __setupPuppetEvents() puppet.on(login) (listenerCount:1) registering...
13:37:49 VERB PuppetMixin __setupPuppetEvents() puppet.on(logout) (listenerCount:1) registering...
13:37:49 VERB PuppetMixin __setupPuppetEvents() puppet.on(message) (listenerCount:0) registering...
13:37:49 VERB PuppetMixin __setupPuppetEvents() puppet.on(room-invite) (listenerCount:0) registering...
13:37:49 VERB PuppetMixin __setupPuppetEvents() puppet.on(room-join) (listenerCount:0) registering...
13:37:49 VERB PuppetMixin __setupPuppetEvents() puppet.on(room-leave) (listenerCount:0) registering...
13:37:49 VERB PuppetMixin __setupPuppetEvents() puppet.on(room-topic) (listenerCount:0) registering...
13:37:49 VERB PuppetMixin __setupPuppetEvents() puppet.on(scan) (listenerCount:0) registering...
13:37:49 VERB PuppetMixin __setupPuppetEvents() puppet.on(dirty) (listenerCount:0) registering...
13:37:49 VERB PuppetMixin __setupPuppetEvents() puppet.on(dong) (listenerCount:0) registering...
13:37:49 VERB PuppetMixin __setupPuppetEvents() puppet.on(error) (listenerCount:0) registering...
13:37:49 VERB PuppetMixin __setupPuppetEvents() puppet.on(heartbeat) (listenerCount:0) registering...
13:37:49 VERB PuppetMixin __setupPuppetEvents() puppet.on(ready) (listenerCount:0) registering...
13:37:49 VERB PuppetMixin __setupPuppetEvents() puppet.on(reset) (listenerCount:0) registering...
13:37:49 VERB WechatyPuppetMixin __setupPuppetEvents() ... done
13:37:49 VERB WechatyPuppetMixin __initPuppetInstance() setting up events ... done
13:37:49 VERB WechatyPuppetMixin __initPuppetInstance() emitting "puppet" event ...
13:37:49 VERB WechatyPuppetMixin __initPuppetInstance() emitting "puppet" event ... done
13:37:49 VERB WechatyPuppetMixin start() initializing puppet instance ... done
13:37:49 VERB WechatyPuppetMixin start() starting puppet ...
13:37:49 VERB PuppetServiceMixin start()
13:37:49 VERB ServiceCtl<PuppetServiceMixin> start()
13:37:49 SILL StateSwitch <PuppetServiceMixin> active() is false
13:37:49 SILL StateSwitch <PuppetServiceMixin> inactive() is true
13:37:49 SILL StateSwitch <PuppetServiceMixin> active() is false
13:37:49 VERB StateSwitch <PuppetServiceMixin> active(pending) <- (false)
13:37:49 VERB ServiceCtl<PuppetServiceMixin> start() super.start() ...
13:37:49 VERB PuppetCacheMixin start()
13:37:49 VERB PuppetLoginMixin start()
13:37:49 VERB PuppetMemoryMixin start()
13:37:49 VERB PuppetSkeleton start()
13:37:49 VERB PuppetCacheAgent start()
13:37:49 VERB PuppetCacheAgent clear()
13:37:49 VERB PuppetCacheMixin start() "dirty" event listener added
13:37:49 VERB ServiceCtl<PuppetServiceMixin> start() super.start() ... done
13:37:49 VERB ServiceCtl<PuppetServiceMixin> start() this.onStart() ...
13:37:49 VERB PuppetService onStart()
13:37:49 VERB PuppetService start() instanciating GrpcManager ...
13:37:49 VERB GrpcManager constructor({"endpoint":"0.0.0.0:8788","token":"puppet_test_whatsoever"})
13:37:49 VERB GrpcManager constructor() tlsRootCert(hash): "88ab8b62777f0fb1179ec567c5019c31d646428cc0a3fdb007fcffa1e9fac5a8"
13:37:49 VERB GrpcManager constructor() token: "puppet_test_whatsoever"
13:37:49 VERB GrpcManager constructor() endpoint: "0.0.0.0:8788"
13:37:49 VERB GrpcManager constructor() disableTls: "false"
13:37:49 VERB GrpcManager constructor() serverName(SNI): "puppet_test"
13:37:49 VERB PuppetService start() instanciating GrpcManager ... done
13:37:49 VERB PuppetService start() setting up bridge grpc event stream ...
13:37:49 VERB PuppetService bridgeGrpcEventStream(client)
13:37:49 VERB PuppetService start() setting up bridge grpc event stream ... done
13:37:49 VERB PuppetService start() starting grpc manager...
13:37:49 VERB GrpcManager start()
13:37:49 VERB GrpcManager start() initializing client ...
13:37:49 VERB GrpcManager initClient()
13:37:49 VERB GrpcManager initClient() TLS: enabled
13:37:49 VERB GrpcManager initClient() ... done
13:37:49 VERB GrpcManager start() initializing client ... done
13:37:49 VERB GrpcManager start() starting stream ...
13:37:49 VERB GrpcManager startStream()
13:37:49 VERB GrpcManager startStream() grpc -> event() ...
13:37:49 VERB GrpcManager startStream() grpc -> event() ... done
13:37:49 VERB GrpcManager startStream() grpc -> event peeking data or timeout ...
13:37:49 VERB GrpcManager startStream() grpc -> event peeking data or timeout ... timeout
13:37:49 VERB GrpcManager startStream() grpc -> event peeking data or timeout ... data peeked
13:37:49 VERB GrpcManager startStream() initializing event stream ...
13:37:49 VERB GrpcManager startStream() initializing event stream ... done
13:37:49 VERB GrpcManager startStream() ... done
13:37:49 VERB GrpcManager start() starting stream ... done
13:37:49 VERB GrpcManager start() calling grpc server: start() ...
13:37:49 ERR Config ###########################
13:37:49 ERR Config Wechaty unhandledRejection: Error: 14 UNAVAILABLE: No connection established
    at Object.callErrorFromStatus (/Users/myonlystarcn/LocalDocuments/code/work/wechaty-1.0/test/node_modules/@grpc/grpc-js/src/call.ts:81:24)
    at Object.onReceiveStatus (/Users/myonlystarcn/LocalDocuments/code/work/wechaty-1.0/test/node_modules/@grpc/grpc-js/src/client.ts:343:36)
    at Object.onReceiveStatus (/Users/myonlystarcn/LocalDocuments/code/work/wechaty-1.0/test/node_modules/@grpc/grpc-js/src/client-interceptors.ts:462:34)
    at Object.onReceiveStatus (/Users/myonlystarcn/LocalDocuments/code/work/wechaty-1.0/test/node_modules/@grpc/grpc-js/src/client-interceptors.ts:424:48)
    at /Users/myonlystarcn/LocalDocuments/code/work/wechaty-1.0/test/node_modules/@grpc/grpc-js/src/call-stream.ts:323:24
    at processTicksAndRejections (node:internal/process/task_queues:78:11) [object Promise]
13:37:49 ERR Config ###########################
huan commented

It seems you want to run some code very like (almost the same) https://github.com/wechaty/puppet-service/blob/main/tests/integration.spec.ts

Can you run this unit test in your environment and see if it works for you?

Please also pay attention to the below code:

puppet-service/tests/grpc-stream.spec.ts

Lines 34 to 43 in 32d400f

test('gRPC client breaks', async t => {
/**
* Huan(202110):
* `insecure_` prefix is required for the TLS version of Puppet Service
* because the `insecure` will be the SNI name of the Puppet Service
* and it will be enforced for the security (required by TLS)
*/
const TOKEN = 'insecure_token'
const PORT = await getPort()
const ENDPOINT = '0.0.0.0:' + PORT

Server Name Indication (SNI) in Wechaty Puppet Service Token (WPST) in v1.x

The Wechaty v1.x ecosystem enforces the Wechaty Puppet Service Token (WPST) to have a Server Name Indication (SNI) so that the TLS can be enabled by default.

insecure_ prefix is required for the TLS version of Puppet Service because the insecure will be the SNI name of the Puppet Service and it will be enforced for the security (required by TLS)

This means that, if the Puppet Service wants to enable the TLS, it needs to have a signed CA for its SNI.

For example, the WXWork token can be named as wxwork_xxxx-xxxx-xxxx-xxxxxxxx, in this name, the wxwork is the SNI.

Tip: we have a token helper named wechaty-token, learn more at https://github.com/wechaty/token

Action List

  1. define the SNI for WXWork Puppet Service: wxwork would be great
  2. sign a CA for WXWork SNI by the wechaty puppet service so that Juzi can use this CA for providing the puppet service with TLS enabled by default.

CC @windmemory for the SNI information.

hcfw007 commented

Indeed they are almost identical since I use puppet-mock to rule-out the possible problem of the puppet module. And yes the unit test passes.

tests/integration.spec.ts 2> 14:26:35 WARN EventStreamManager this.onStreamingCallEnd() this.eventStream.on(finish) eventStream is undefined
tests/integration.spec.ts 2> 14:26:35 WARN EventStreamManager this.onStreamingCallEnd() this.eventStream.on(close) eventStream is undefined
tests/integration.spec.ts 2> 14:26:35 WARN EventStreamManager this.onStreamingCallEnd() this.eventStream.on(cancelled) eventStream is undefined
​ PASS ​ tests/integration.spec.ts 4 OK 1s

I also tried to rerun my code after changing token to 'insecure_testtoken' and the problem solved.

For the SNI issue, I think that's beyond my pay grade LOL. I'll keep them updated.

huan commented

Glad to know that your issue has been solved.

And we can confirm this is a SNI issue, we can keep eyes on it for the future works.

  • 🎉1
hcfw007 commented

Is there any rules about SNI naming? I mean can there be a underline in SNI, so that we can continue using puppet_wxwork as SNI?

huan commented

Thanks for asking!

The SNI is designed with the following rules:

  1. Wechaty Token format standard released: SNI_UUID (learn more)
  2. The SNI will be extracted from the token string before the last _ occurred, which should be compatible with our current using ones, like puppet_wxwork_XXX. (source code)
  3. If you want to make sure your token with SNI is supported by our ecosystem, you can add unit tests to guard it at this unit test
  4. Learn the insecure SNI at here, and with TLS the user can only DIY insecure_XXX tokens by themselves start with Wechaty 1.x.

CC @wechaty/puppet @wechaty/polyglot

hcfw007 commented

1.define the SNI for WXWork Puppet Service: wxwork would be great
2.sign a CA for WXWork SNI by the wechaty puppet service so that Juzi can use this CA for providing the puppet service with TLS enabled by default.

  1. We wish to continue using puppet_wxwork as our SNI
  2. Sorry I'm not familiar with CA. Could you please explain how to sign a CA? I did some search and only find methods to create a self-signed CA. Is that what you need?
huan commented
  1. We wish to continue using puppet_wxwork as our SNI

That should be already supported out-of-the-box.

The Wechaty community will use the private CA to sign a puppet-wxwork CA for you so that it can be secure.

I'm planning to design a form so that the puppet service providers in our community can submit applications via it, please stay tuned.

  • 👍1
hcfw007 commented

Sorry, there seems to be something wrong with puppet_wxwork support.

I started a wxwork puppet locally, and set it up with different tokens, then connect it with puppet-service.

token result
insecure_testtoken succeess
puppet_wxwork_test 14 UNAVAILABLE: No connection established
puppet_wxwork_782b1da6e5d0f694 14 UNAVAILABLE: No connection established
puppet_wxwork_a69954dd-432d-4562-87af-856a638190f0 14 UNAVAILABLE: No connection established

puppet_wxwork_782b1da6e5d0f694 is generated by our current token generator, and puppet_wxwork_a69954dd-432d-4562-87af-856a638190f0 is generated by wechaty-token

huan commented

It will be expected to not work because you have no valid CA with SNI puppet_wxwork.

In order to make it work, you must obtain the signed CA with SNI puppet-wxwork first.

I'll try to generate one and send it to you for testing purposes later.

  • 🎉1
hcfw007 commented

Hello @huan , sorry to bother you, but how is the CA generating going?

huan commented

@hcfw007 I have sent the generated CA to @windmemory as an email, please ask him to forward it to you. (because I haven't your email address)

Feel free to let me know if you have any questions by comment this issue.

hcfw007 commented

How should I use this CA?

huan commented

Please refer to my email, thank you very much.

huan commented

Have we tested the CA already or not?

Please let me know the process and I'd like to help.

Thanks.

hcfw007 commented

Not yet. So far we focus on functionality test with TLS disabled.
As we want to upgrade bot side and service side asynchronously, there were quite a lot compatibility work to do (such as the dirty problem. ).
Anyway I'll post any updates about CA here. Thank you for your concern.