人脸解锁设备时出现相机报错

（1）背景分析

这是项目当中实际遇到的问题，如下代码仅用作分析和记录。

现在问题的现象是：刚亮屏大概在2s以内对着人脸一般是能解锁的，但是超过2s之后在对着人脸，是无法解锁成功的。

（2）Log分析

（A）从kernel Log分析

从Log来看，相机模组是有正常上电的，表示相机是有正常启动的。

//cat dev/kmsg | grep ov8856
6,1707232,24357395110,-; (0)[22056:powerOnSensor0]sensor_idx 1, power 1 curr_sensor_name ov8856_mipi_raw, enable list NULL
4,1707233,24357395119,-; (0)[22056:powerOnSensor0]sensor_idx = 1, pin=7, pin_state_on=11, hw_id =2, hctzhb(ov8856_mipi_raw)
4,1707234,24357395135,-; (0)[22056:powerOnSensor0]sensor_idx = 1, pin=5, pin_state_on=7, hw_id =0, hctzhb(ov8856_mipi_raw)
4,1707235,24357395587,-; (0)[22056:powerOnSensor0]sensor_idx = 1, pin=3, pin_state_on=9, hw_id =0, hctzhb(ov8856_mipi_raw)
4,1707236,24357396060,-; (1)[22056:powerOnSensor0]sensor_idx = 1, pin=4, pin_state_on=3, hw_id =0, hctzhb(ov8856_mipi_raw)
4,1707237,24357398161,-; (1)[22056:powerOnSensor0]sensor_idx = 1, pin=6, pin_state_on=9, hw_id =0, hctzhb(ov8856_mipi_raw)
4,1707238,24357400667,-; (1)[22056:powerOnSensor0]sensor_idx = 1, pin=1, pin_state_on=0, hw_id =1, hctzhb(ov8856_mipi_raw)
4,1707239,24357400690,-; (1)[22056:powerOnSensor0]sensor_idx = 1, pin=1, pin_state_on=11, hw_id =1, hctzhb(ov8856_mipi_raw)
4,1707240,24357400698,-; (1)[22056:powerOnSensor0]sensor_idx = 1, pin=2, pin_state_on=0, hw_id =1, hctzhb(ov8856_mipi_raw)
4,1707241,24357400707,-; (1)[22056:powerOnSensor0]sensor_idx = 1, pin=2, pin_state_on=11, hw_id =1, hctzhb(ov8856_mipi_raw)

（B）从main Log分析

D MtkCam/P1NodeImp: [init] +
D MtkCam/P1NodeImp: [init] -I MtkCam/P1NodeImp: [hardwareOps_start] [Cam::1] mpCamIO->init +++
I MtkCam/P1NodeImp: [hardwareOps_start] [Cam::1] mpCamIO->init ---I MtkCam/P1NodeImp: [hardwareOps_start] [Cam::1] mpCamIO->configPipe +++
I MtkCam/P1NodeImp: [hardwareOps_start] [Cam::1] mpCamIO->configPipe ---I MtkCam/P1NodeImp: [hardwareOps_start] [Cam::1] mp3A->start +++
I MtkCam/P1NodeImp: [hardwareOps_start] [Cam::1] mpISP->start +++I MtkCam/P1NodeImp: [hardwareOps_start] [Cam::1] mpCamIO->start +++
I MtkCam/P1NodeImp: [hardwareOps_start] [Cam::1] mpCamIO->start ---

可以看出，相机的Hal P1流程是有正常走的，而我们看一下P1是否有接收到数据。

I MtkCam/P1NodeImp: [setRequest] [Cam::1 R2 S2 E1 D1 O1 #0] [P1::SET][Num Q:2 M:2 F:0 R:0 @0][Type:1 Out:x81 Rec:x0 Raw:0 Cap:0 Exe:1 Flush:x0] Num[2] Ctrl[1]=[ 2 ]
I MtkCam/P1NodeImp: [setRequest] [Cam::1 R3 S3 E2 D1 O1 #1] [P1::SET][Num Q:3 M:3 F:1 R:1 @0][Type:1 Out:x81 Rec:x0 Raw:0 Cap:0 Exe:1 Flush:x0] Num[3] Ctrl[1]=[ 3 ]
I MtkCam/P1NodeImp: [setRequest] [Cam::1 R4 S4 E3 D1 O1 #1] [P1::SET][Num Q:4 M:4 F:2 R:2 @0][Type:1 Out:x81 Rec:x0 Raw:0 Cap:0 Exe:1 Flush:x0] Num[4] Ctrl[1]=[ 4 ]
I MtkCam/P1NodeImp: [setRequest] [Cam::1 R5 S5 E4 D2 O2 #0] [P1::SET][Num Q:5 M:5 F:3 R:3 @0][Type:1 Out:x81 Rec:x0 Raw:0 Cap:0 Exe:1 Flush:x0] Num[5] Ctrl[1]=[ 5 ]
I MtkCam/P1NodeImp: [setRequest] [Cam::1 R6 S6 E5 D3 O3 #1] [P1::SET][Num Q:6 M:6 F:4 R:4 @0][Type:1 Out:x81 Rec:x0 Raw:0 Cap:0 Exe:1 Flush:x0] Num[6] Ctrl[1]=[ 6 ]
I MtkCam/P1NodeImp: [setRequest] [Cam::1 R7 S7 E6 D4 O4 #0] [P1::SET][Num Q:7 M:7 F:5 R:5 @0][Type:1 Out:x81 Rec:x0 Raw:0 Cap:0 Exe:1 Flush:x0] Num[7] Ctrl[1]=[ 7 ]
I MtkCam/P1NodeImp: [setRequest] [Cam::1 R8 S8 E7 D5 O5 #0] [P1::SET][Num Q:8 M:8 F:6 R:6 @0][Type:1 Out:x81 Rec:x0 Raw:0 Cap:0 Exe:1 Flush:x0] Num[8] Ctrl[1]=[ 8 ]
//异常Log
I MtkCam/P1NodeImp: [setRequest] [Cam::1 R9 S9 E8 D6 O6 #0] [P1::SET][Num Q:9 M:9 F:-1 R:-1 @0][Type:3 Out:x82 Rec:x0 Raw:0 Cap:0 Exe:1 Flush:x0] Num[9] Ctrl[1]=[ 9 ]
I MtkCam/P1NodeImp: [setRequest] [Cam::1 R10 S10 E9 D7 O7 #0] [P1::SET][Num Q:10 M:10 F:-1 R:-1 @0][Type:3 Out:x82 Rec:x0 Raw:0 Cap:0 Exe:1 Flush:x0] Num[10] Ctrl[1]=[ 10 ]

从上面的Log可以看到，当超过7 frames之后，P1并不是真正的在出帧了，而是P1在做垫帧，我们在来看一下P2是否有接收到数据。

D MtkCam/P2/StreamingNode: [init+] P2S cam 1:
D MtkCam/P2/StreamingNode: [init-] P2S cam 1:D MtkCam/P2/StreamingNode: [config+] P2S cam 1:
D MtkCam/P2/StreamingNode: [config-] P2S cam 1:D MtkCam/P2/StreamingProcessor: [onThreadStart+] P2S cam 1: 
D MtkCam/P2/StreamingProcessor: [onThreadStart-] P2S cam 1: 

可以看出，相机的Hal P2流程也是有正常走的，而我们看一下P2是否有接收到数据。

D MtkCam/P2/MWFrameRequest: [printIOMap] P2S cam 1 MWFrame:#0 MWReq:#0, frame 1 : iomap: [0]=>img[1/1], meta[3/2], fps[0.00]
D MtkCam/P2/MWFrameRequest: [printIOMap] P2S cam 1 MWFrame:#1 MWReq:#1, frame 2 : iomap: [0]=>img[1/1], meta[3/2], fps[30.30]
D MtkCam/P2/MWFrameRequest: [printIOMap] P2S cam 1 MWFrame:#2 MWReq:#2, frame 3 : iomap: [0]=>img[1/1], meta[3/2], fps[29.41]
D MtkCam/P2/MWFrameRequest: [printIOMap] P2S cam 1 MWFrame:#3 MWReq:#3, frame 4 : iomap: [0]=>img[1/1], meta[3/2], fps[28.85]
D MtkCam/P2/MWFrameRequest: [printIOMap] P2S cam 1 MWFrame:#4 MWReq:#4, frame 5 : iomap: [0]=>img[1/1], meta[3/2], fps[29.63]
D MtkCam/P2/MWFrameRequest: [printIOMap] P2S cam 1 MWFrame:#5 MWReq:#5, frame 6 : iomap: [0]=>img[1/1], meta[3/2], fps[29.76]
D MtkCam/P2/MWFrameRequest: [printIOMap] P2S cam 1 MWFrame:#6 MWReq:#6, frame 7 : iomap: [0]=>img[1/1], meta[3/2], fps[28.99]

从Log来看，P2也是只接收到7 frames，就再也没收接收到Request请求了。

（3）根本原因

以上种种分析可以看到，实际上Hal只接受到了7frames的request，那我们看一下实际是否是这样的呢？通过搜索ULog发现：

D ULog    : R AppRequest:0 M[CameraDevice:187001] +  :mtkcam-dev3 #1990
D ULog    : R AppRequest:1 M[CameraDevice:187001] +  :mtkcam-dev3 #1993
D ULog    : R AppRequest:2 M[CameraDevice:187001] +  :mtkcam-dev3 #1994
D ULog    : R AppRequest:3 M[CameraDevice:187001] +  :mtkcam-dev3 #1995
D ULog    : R AppRequest:4 M[CameraDevice:187001] +  :mtkcam-dev3 #1996
D ULog    : R AppRequest:5 M[CameraDevice:187001] +  :mtkcam-dev3 #1998
D ULog    : R AppRequest:6 M[CameraDevice:187001] +  :mtkcam-dev3 #2000D ULog    : R AppRequest:0 M[CameraDevice:187001] -  :mtkcam-AppStreamMgr #1997
D ULog    : R AppRequest:1 M[CameraDevice:187001] -  :mtkcam-AppStreamMgr #1999
D ULog    : R AppRequest:2 M[CameraDevice:187001] -  :mtkcam-AppStreamMgr #2001
D ULog    : R AppRequest:3 M[CameraDevice:187001] -  :mtkcam-AppStreamMgr #2002
D ULog    : R AppRequest:4 M[CameraDevice:187001] -  :mtkcam-AppStreamMgr #2003
D ULog    : R AppRequest:5 M[CameraDevice:187001] -  :mtkcam-AppStreamMgr #2004
D ULog    : R AppRequest:6 M[CameraDevice:187001] -  :mtkcam-AppStreamMgr #2005

实际上层只发送了7 frames的request。所以才造成P1和P2都只有7 frames的有效数据。

通过排查Log报错发现，有以下Error：

06-05 13:59:11.621877   829 15363 E HidlCamera3-Device: processBatchCaptureRequests: Transaction error: Status(EX_TRANSACTION_FAILED): 'FAILED_TRANSACTION: '
06-05 13:59:11.621932   829 15363 E Camera3-Device: Camera 1: sendRequestsBatch: RequestThread: Unable to submit capture request 7 to HAL device: Broken pipe (-32)

可以看到是Framework层发送request报错了，从而导致request无法下到Hal。那引起发送request失败的原因是什么？我们在从Log中发现如下：

W C3Dev-1-ReqQueu: type=1400 audit(0.0:649): avc: denied { use } for path="anon_inode:sync_file" dev="anon_inodefs" ino=6816 scontext=u:r:mtk_hal_camera:s0 tcontext=u:r:hal_face_default:s0 tclass=fd permissive=0

看起来像是avc权限导致的，我们使用setenforce 0测试一下发现确实这里就是根本原因了。