一天,业务开发同学反馈了一个 RN 的问题,RN 项目在 Android APP 中启动后报如下错误导致崩溃:
E/unknown:React: Exception in native call java.lang.RuntimeException: Error calling RCTDeviceEventEmitter.emit at com.facebook.react.bridge.queue.NativeRunnable.run(Native Method) at android.os.Handler.handleCallback(Handler.java:754) at android.os.Handler.dispatchMessage(Handler.java:95) at com.facebook.react.bridge.queue.MessageQueueThreadHandler.dispatchMessage(MessageQueueThreadHandler.java:31) at android.os.Looper.loop(Looper.java:163) at com.facebook.react.bridge.queue.MessageQueueThreadImpl$3.run(MessageQueueThreadImpl.java:204) at java.lang.Thread.run(Thread.java:760) Caused by: com.facebook.jni.CppException: Failed to create String from JSON: at com.facebook.react.bridge.queue.NativeRunnable.run(Native Method) at android.os.Handler.handleCallback(Handler.java:754) at android.os.Handler.dispatchMessage(Handler.java:95) at com.facebook.react.bridge.queue.MessageQueueThreadHandler.dispatchMessage(MessageQueueThreadHandler.java:31) at android.os.Looper.loop(Looper.java:163) at com.facebook.react.bridge.queue.MessageQueueThreadImpl$3.run(MessageQueueThreadImpl.java:204) at java.lang.Thread.run(Thread.java:760)
我们立刻展开分析,根据报错信息这是在执行 RCTDeviceEventEmitter.emit
方法的时候报出来的错,原因是 C++ 抛出的一个错误 Failed to create String from JSON:
。根据业务同学提供的重现步骤和一些信息重现了问题,初步梳理出如下线索:
开始怀疑 RN 无法解析 emoji 字符,但是很快被上述第二条线索否定了,因为预发环境的请求结果与线上一致,也包含 emoji(并且抓包对比两个环境的返回结果确认完全一样)。
就在一筹莫展的时候,泽义同学提到网络请的求返回结果是原生通过 DeviceEventEmitter 传给 JS 的,很有可能就是在这里报错的,可以尝试在 JS 端接受到事件的时候打印日志对比一下线上环境和预发环境的区别。
这里要向读者提一句,我们的 RN 项目在线上环境为了防止打印多余日志,重写了 window.console
对象,并且顺带初始化了 RN 的 sentry sdk(一个错误日志收集系统):
import Console from 'custom-sentry-sdk'; window.console = new Console({ dsn, options });
因此如果想使用 console.log
打印日志,需要注释掉上面的代码。然而就在注释掉并重新运行项目后,发现没有报错了!没有报错了!!
于是我们放下对比日志的工作,开始对 sentry sdk 源码进行拷问,使用“删除代码定位法”辅以二分法,最终找到了问题所在,拎出来示众:
// raven-js/src/raven.js // if onreadystatechange wasn't actually set by the page on this xhr, we // are free to set our own and capture the breadcrumb xhr.onreadystatechange = onreadystatechangeHandler;
sentry sdk 代理了 XMLHttpRequest 的 onreadystatechange
事件,用于收集错误日志产生前所发生的网络请求,而我们平常用 fetch 方法不会监听这个事件(axios 会监听这个事件获取响应数据),就是这个操作导致的最终结果不一样,至于为什么,这里留下一个疑团。
我们继续对比日志, window.console
的重写代码既然不能注释掉,我们就想办法获取到了原始的 console 对象,下面是打印出来的一个请求过程中 JS 接收到的原生事件以及参数:
didReceiveNetworkResponse [1, 200, '<Response Header>'] didReceiveNetworkData [1, '<Response Body>'] didCompleteNetworkResponse [1, null]
didReceiveNetworkResponse [1, 200, '<Response Header>'] didReceiveNetworkIncrementalData [1, '<Response Body0>'] didReceiveNetworkIncrementalData [1, '<Response Body1>'] didReceiveNetworkIncrementalData [1, '<Response Body2>'] didReceiveNetworkIncrementalData [1, '<Response Body3>'] didReceiveNetworkIncrementalData [1, '<Response Body4>'] didReceiveNetworkIncrementalData [1, '<Response Body5>'] didCompleteNetworkResponse [1, null]
didReceiveNetworkResponse [1, 200, '<Response Header>'] didReceiveNetworkIncrementalData [1, '<Response Body0>'](一部分数据) didCompleteNetworkResponse [1, null] (报错)
根据日志对于每个请求 JS 端都收到了 didReceiveNetworkResponse
和 didCompleteNetworkResponse
并且参数相同,不同的是接收到 response body
的方式不同,总结几个现象:
response body response body response body
得出的结论是监听 onreadystatechange
事件会导致原生响应请求数据时分片,而分片又出于某种原因导致 C++ 解析字符串报错。基于这个结论我们产生了一个想法,一个 emoji 是多个字节组成的,如果分片切割的时候恰好从 emoji 中间切开,emoji 的前半部分被分在了前一个分片的末尾,后半部分被分在了后一个分片的开头,如图所示:
为了证实这个猜想,我们不得不踏上前往原生世界的“冒险”。JS 如果希望发起一个网络请求,需要向原生发送请求信息,我们注意到这其中有一个参数 incrementalEvents
,认为这个是决定响应数据是否分片的一个参数,上面提到的 sentry sdk 监听 onreadystatechange
事件,会让 incrementalEvents
参数变为 true
,留下的疑团也解开了:
// XMLHttpRequest.js send(data) { // ... // 如果 onredystatechange 设置了监听函数,则 incrementalEvents 为 true const incrementalEvents = this._incrementalEvents || !!this.onreadystatechange || !!this.onprogress; // ... // 发往原生 RCTNetworking.sendRequest( this._method, this._trackingName, this._url, this._headers, data, nativeResponseType, incrementalEvents, this.timeout, this.__didCreateRequest.bind(this), ); }
继续前行,我们在 RN 的原生网络模块中发现了一些逻辑证实了上面的想法。Java 在 http 请求收到响应后判断 useIncrementalUpdates
如果为 true,就每次尝试从 response body stream
中读取 16KiB 的数据,读完一次马上使用事件通知 JS,直到读不出数据为止:
// com.facebook.react.modules.network.NetworkingModule Reader reader = responseBody.charStream(); try { char[] buffer = new char[8 * 1024]; int read; while ((read = reader.read(buffer)) != -1) { ResponseUtil.onIncrementalDataReceived( eventEmitter, requestId, new String(buffer, 0, read), totalBytesRead, contentLength); } } finally { reader.close(); }
通过断点调试,断定了就是 emoji 被切到了两片中去,下面是每次循环中的 buffer
内容:
[123, 34, ... , 67, 68] char[8 * 1024],从 response body stream 中读取 16KiB 数据 [123, 34, ... , 23458, 55356] char[8 * 1024],从 response body stream 中读取 16KiB 数据 [56728, 34, ... , 42, 89] char[8 * 1024],从 response body stream 中读取 16KiB 数据 . . .
上面的 buffer
是由 char 组成的数组,每个 char 能表示两个字节的数据,第二片数据的末尾和第三片的开头的 char 正好能组成一个 4 字节的 emoji 字符, String.fromCharCode(55356, 56728) // :sos:
,而 JSC 的 JSValueMakeFromJSONString
方法认为单独的 55356
是一个非法的 UTF-8 字符,从而导致最开始提到的报错,谜题全部解开了。
至于解决方案,开始在网上搜了一下没找到有用的信息,在搞清楚问题的原因后,马上就发现新版 RN 已经有人提 PR 解决了这个问题,方法是对当前分片的字节数据进行 UTF-8(默认)解码,如果有无法解码的字节数据,就把无法解码的部分加到下一个分片的开头。只要给我们的 RN 版本打上这个补丁就好了。
这过程中曾经偶然尝试了其它 APP 上跑同样的代码,却不会出现上述问题,调试发现分片情况如下:
[123, 34, ... , 40, 42, 0, 0, 0, 0, ...] char[8 * 1024],从 response body stream 中读取 1KiB 数据 [123, 34, ... , 55356, 56728, 0, 0, 0, 0, ...] char[8 * 1024],从 response body stream 中读取 5KiB 数据 [67, 34, ... , 42, 89, 0, 0, 0, 0, ...] char[8 * 1024],从 response body stream 中读取 3KiB 数据 . . .
这些分片长度不足 16KiB,看上去每次从 stream 读出随机数量的数据到 buffer
中,并且使用模拟数据进行了多次试验,每次分片都会刚好避免上文提到的 emoji 切割情况,感觉和 InputStreamReader 中的解码器有关系。
为什么上面有问题的 APP 每次都能从 stream 读出 16KiB 的数据呢,经过调试发现,APP 中的另一个 sdk 会收集 RN 的网络请求信息,会使用拦截器预先读一遍 stream(根据 okhttp 文档,这个属于正规操作),等到 RN 正常流程去读的时候,数据都已经缓冲好了。但是为什么数据缓冲过之后,就不能正常解码了呢,那又是另外一个故事了。