linux icon indicating copy to clipboard operation
linux copied to clipboard
verified publisher icon raspberrypi

kernel-side crash for a bad CSI device: v4l2-subdev.c:457 call_s_stream+0xe8/0x110 [videodev]

Open xrdelectro opened this issue 5 months ago • 3 comments

Describe the bug

Posting in case someone might be interested in having a look at the crash dump and making kernel-side code more robust against faulty (or badly soldered) units.

some kernel module crash seemed to be provoked when a badly soldered imx290 CSI camera unit was attached and libcamera-hello was run.

As far as I understood/remember, a weird edge case was provoked, where same subdev release/deallocation occured more times than necessary when after a failure to initialize HW... or something along those lines.

I have fixed resoldered/fixed my camera unit, so probably won't be reproducing this issue for some time now.

What I noticed as well - an issue stopped to occur when I recompiled at that time latest rpicam-apps and libcamera and installed that on top of the latest updated 6.12.y system (between 7th and 11th of July), I think that from the logs you should see all the versions needed.

Cheers, Zigmārs

Steps to reproduce the behaviour

hardly possible - must have bad/misconfigured hardware (XMASTER for IMX291 was set incorrectly - as slave), might have had some MIPI lane connections missing.

Device (s)

Raspberry Pi 5

System

This is an old issue I have fixed for myself, so only way is to look at the versions dumped in logs.

Logs

$ LIBCAMERA_LOG_LEVELS=*:DEBUG libcamera-hello
[0:02:40.540027976] [1140] DEBUG IPAModule ipa_module.cpp:333 ipa_rpi_pisp.so: IPA module /usr/lib/aarch64-linux-gnu/libcamera/ipa_rpi_pisp.so is signed
[0:02:40.541292897] [1140] DEBUG IPAManager ipa_manager.cpp:229 Loaded IPA module '/usr/lib/aarch64-linux-gnu/libcamera/ipa_rpi_pisp.so'
[0:02:40.613992816] [1140] DEBUG IPAModule ipa_module.cpp:333 ipa_rpi_vc4.so: IPA module /usr/lib/aarch64-linux-gnu/libcamera/ipa_rpi_vc4.so is signed
[0:02:40.614047151] [1140] DEBUG IPAManager ipa_manager.cpp:229 Loaded IPA module '/usr/lib/aarch64-linux-gnu/libcamera/ipa_rpi_vc4.so'
[0:02:40.614069875] [1140]  INFO Camera camera_manager.cpp:326 libcamera v0.5.0+59-d83ff0a4
[0:02:40.614190194] [1145] DEBUG Camera camera_manager.cpp:73 Starting camera manager
[0:02:40.620483858] [1145] DEBUG DeviceEnumerator device_enumerator.cpp:230 New media device "rp1-cfe" created from /dev/media2
[0:02:40.620586677] [1145] DEBUG DeviceEnumerator device_enumerator_udev.cpp:96 Defer media device /dev/media2 due to 10 missing dependencies
[0:02:40.621649072] [1145] DEBUG DeviceEnumerator device_enumerator_udev.cpp:322 All dependencies for media device /dev/media2 found
[0:02:40.621658387] [1145] DEBUG DeviceEnumerator device_enumerator.cpp:258 Added device /dev/media2: rp1-cfe
[0:02:40.621726186] [1145] DEBUG DeviceEnumerator device_enumerator.cpp:230 New media device "rpi-hevc-dec" created from /dev/media3
[0:02:40.621736649] [1145] DEBUG DeviceEnumerator device_enumerator_udev.cpp:96 Defer media device /dev/media3 due to 1 missing dependencies
[0:02:40.621848969] [1145] DEBUG DeviceEnumerator device_enumerator_udev.cpp:322 All dependencies for media device /dev/media3 found
[0:02:40.621857024] [1145] DEBUG DeviceEnumerator device_enumerator.cpp:258 Added device /dev/media3: rpi-hevc-dec
[0:02:40.621935157] [1145] DEBUG DeviceEnumerator device_enumerator.cpp:230 New media device "pispbe" created from /dev/media0
[0:02:40.621945176] [1145] DEBUG DeviceEnumerator device_enumerator_udev.cpp:96 Defer media device /dev/media0 due to 8 missing dependencies
[0:02:40.622027068] [1145] DEBUG DeviceEnumerator device_enumerator.cpp:230 New media device "pispbe" created from /dev/media1
[0:02:40.622036791] [1145] DEBUG DeviceEnumerator device_enumerator_udev.cpp:96 Defer media device /dev/media1 due to 8 missing dependencies
[0:02:40.622838861] [1145] DEBUG DeviceEnumerator device_enumerator_udev.cpp:322 All dependencies for media device /dev/media0 found
[0:02:40.622847454] [1145] DEBUG DeviceEnumerator device_enumerator.cpp:258 Added device /dev/media0: pispbe
[0:02:40.623637912] [1145] DEBUG DeviceEnumerator device_enumerator_udev.cpp:322 All dependencies for media device /dev/media1 found
[0:02:40.623645949] [1145] DEBUG DeviceEnumerator device_enumerator.cpp:258 Added device /dev/media1: pispbe
[0:02:40.623930701] [1145] DEBUG Camera camera_manager.cpp:140 Found registered pipeline handler 'rpi/vc4'
[0:02:40.625878725] [1145] DEBUG RPI vc4.cpp:189 Unable to acquire a Unicam instance
[0:02:40.625899337] [1145] DEBUG RPI vc4.cpp:189 Unable to acquire a Unicam instance
[0:02:40.625914504] [1145] DEBUG Camera camera_manager.cpp:140 Found registered pipeline handler 'rpi/pisp'
[0:02:40.625931135] [1145] DEBUG DeviceEnumerator device_enumerator.cpp:318 Successful match for media device "rp1-cfe"
[0:02:40.625962302] [1145] DEBUG DeviceEnumerator device_enumerator.cpp:318 Successful match for media device "pispbe"
[0:02:40.626053677] [1145] DEBUG ClockRec clock_recovery.cpp:69 configure 100 2000 10 50000
[0:02:40.626071622] [1145] DEBUG ClockRec clock_recovery.cpp:83 reset
[0:02:40.626222369] [1145]  INFO RPI pisp.cpp:720 libpisp version v1.2.1 981977ff21f3 29-04-2025 (14:13:50)
[0:02:40.637526587] [1145] DEBUG CameraSensor camera_sensor_raw.cpp:210 imx290 10-001a: unsupported number of sinks (0) or sources (1)
[0:02:40.637579164] [1145] DEBUG V4L2 v4l2_device.cpp:721 'imx290 10-001a': Control: Exposure (0x00980911)
[0:02:40.637606405] [1145] DEBUG V4L2 v4l2_device.cpp:721 'imx290 10-001a': Control: Horizontal Flip (0x00980914)
[0:02:40.637624777] [1145] DEBUG V4L2 v4l2_device.cpp:721 'imx290 10-001a': Control: Vertical Flip (0x00980915)
[0:02:40.637643944] [1145] DEBUG V4L2 v4l2_device.cpp:721 'imx290 10-001a': Control: Camera Orientation (0x009a0922)
[0:02:40.637666112] [1145] DEBUG V4L2 v4l2_device.cpp:721 'imx290 10-001a': Control: Camera Sensor Rotation (0x009a0923)
[0:02:40.637684649] [1145] DEBUG V4L2 v4l2_device.cpp:721 'imx290 10-001a': Control: Vertical Blanking (0x009e0901)
[0:02:40.637702020] [1145] DEBUG V4L2 v4l2_device.cpp:721 'imx290 10-001a': Control: Horizontal Blanking (0x009e0902)
[0:02:40.637718910] [1145] DEBUG V4L2 v4l2_device.cpp:721 'imx290 10-001a': Control: Analogue Gain (0x009e0903)
[0:02:40.637737077] [1145] DEBUG V4L2 v4l2_device.cpp:721 'imx290 10-001a': Control: Link Frequency (0x009f0901)
[0:02:40.637756838] [1145] DEBUG V4L2 v4l2_device.cpp:721 'imx290 10-001a': Control: Pixel Rate (0x009f0902)
[0:02:40.637774598] [1145] DEBUG V4L2 v4l2_device.cpp:721 'imx290 10-001a': Control: Test Pattern (0x009f0903)
[0:02:40.638174558] [1145] DEBUG CameraSensor camera_sensor_legacy.cpp:525 'imx290 10-001a': No static test pattern map for 'imx290'
[0:02:40.638203633] [1145] DEBUG CameraSensor camera_sensor.cpp:468 Entity 'imx290 10-001a' matched by CameraSensorLegacy
[0:02:40.644551503] [1145] DEBUG IPAManager ipa_manager.cpp:300 IPA module /usr/lib/aarch64-linux-gnu/libcamera/ipa_rpi_pisp.so signature is valid
[0:02:40.644607635] [1145] DEBUG IPAProxy raspberrypi_ipa_proxy.cpp:45 initializing raspberrypi proxy: loading IPA from /usr/lib/aarch64-linux-gnu/libcamera/ipa_rpi_pisp.so
[0:02:40.654430349] [1145] DEBUG RPiBlackLevel black_level.cpp:40  Read black levels red 3840 green 3840 blue 3840
[0:02:40.654559076] [1145] DEBUG RPiAgc agc.cpp:41 Single channel only
[0:02:40.654580855] [1145] DEBUG RPiAgc agc_channel.cpp:223 AgcConfig
[0:02:40.654940647] [1145] DEBUG RPiSharpen sharpen.cpp:45 Read threshold 1 strength 1 limit 1
[0:02:40.655182639] [1145] DEBUG RPiDelayedControls delayed_controls.cpp:103 Set a delay of 2 and priority write flag 1 for Vertical Blanking
[0:02:40.655206991] [1145] DEBUG RPiDelayedControls delayed_controls.cpp:103 Set a delay of 2 and priority write flag 0 for Horizontal Blanking
[0:02:40.655223122] [1145] DEBUG RPiDelayedControls delayed_controls.cpp:103 Set a delay of 2 and priority write flag 0 for Exposure
[0:02:40.655236900] [1145] DEBUG RPiDelayedControls delayed_controls.cpp:103 Set a delay of 2 and priority write flag 0 for Analogue Gain
[0:02:40.655339219] [1145] DEBUG V4L2 v4l2_videodevice.cpp:631 /dev/video4[16:cap]: Opened device platform:1f00110000.csi: rp1-cfe: rp1-cfe
[0:02:40.655387425] [1145] DEBUG V4L2 v4l2_videodevice.cpp:631 /dev/video7[17:out]: Opened device platform:1f00110000.csi: rp1-cfe: rp1-cfe
[0:02:40.655416000] [1145] DEBUG V4L2 v4l2_videodevice.cpp:631 /dev/video6[18:cap]: Opened device platform:1f00110000.csi: rp1-cfe: rp1-cfe
[0:02:40.655442575] [1145] DEBUG V4L2 v4l2_videodevice.cpp:631 /dev/video20[19:out]: Opened device platform:1000880000.pisp_be: pispbe: pispbe
[0:02:40.655509226] [1145] DEBUG V4L2 v4l2_videodevice.cpp:631 /dev/video23[20:cap]: Opened device platform:1000880000.pisp_be: pispbe: pispbe
[0:02:40.655569080] [1145] DEBUG V4L2 v4l2_videodevice.cpp:631 /dev/video24[21:cap]: Opened device platform:1000880000.pisp_be: pispbe: pispbe
[0:02:40.655627638] [1145] DEBUG V4L2 v4l2_videodevice.cpp:631 /dev/video27[22:out]: Opened device platform:1000880000.pisp_be: pispbe: pispbe
[0:02:40.655653750] [1145] DEBUG V4L2 v4l2_videodevice.cpp:631 /dev/video21[23:out]: Opened device platform:1000880000.pisp_be: pispbe: pispbe
[0:02:40.655712660] [1145] DEBUG V4L2 v4l2_videodevice.cpp:631 /dev/video25[24:cap]: Opened device platform:1000880000.pisp_be: pispbe: pispbe
[0:02:40.655770162] [1145] DEBUG V4L2 v4l2_videodevice.cpp:631 /dev/video22[25:out]: Opened device platform:1000880000.pisp_be: pispbe: pispbe
[0:02:40.655827739] [1145] DEBUG V4L2 v4l2_videodevice.cpp:631 /dev/video26[26:cap]: Opened device platform:1000880000.pisp_be: pispbe: pispbe
[0:02:40.655886352] [1145]  INFO RPI pisp.cpp:1179 Registered camera /base/axi/pcie@1000120000/rp1/i2c@88000/imx290@1a to CFE device /dev/media2 and ISP device /dev/media0 using PiSP variant BCM2712_C0
[0:02:40.655911927] [1145] DEBUG Camera camera_manager.cpp:161 Pipeline handler "rpi/pisp" matched
[0:02:40.655928817] [1145] DEBUG RPI pisp.cpp:890 Unable to acquire a CFE instance
[0:02:40.655946762] [1145] DEBUG Camera camera_manager.cpp:140 Found registered pipeline handler 'uvcvideo'
Preview window unavailable
[0:02:40.660969263] [1140] DEBUG RPI pipeline_base.cpp:974 Format: 1280x720 fmt SRGGB10 Score: 3000 (best 3000)
[0:02:40.660992764] [1140] DEBUG RPI pipeline_base.cpp:974 Format: 1920x1080 fmt SRGGB10 Score: 1000 (best 1000)
[0:02:40.661003746] [1140] DEBUG RPI pipeline_base.cpp:974 Format: 1280x720 fmt SRGGB12 Score: 2000 (best 1000)
[0:02:40.661012431] [1140] DEBUG RPI pipeline_base.cpp:974 Format: 1920x1080 fmt SRGGB12 Score: 0 (best 0)
[0:02:40.661031895] [1140] DEBUG Camera camera.cpp:1140 streams configuration: (0) 1920x1080-SRGGB12_CSI2P
[0:02:40.661209032] [1140] DEBUG RPI pipeline_base.cpp:974 Format: 1280x720 fmt SRGGB10 Score: 3000 (best 3000)
[0:02:40.661219680] [1140] DEBUG RPI pipeline_base.cpp:974 Format: 1920x1080 fmt SRGGB10 Score: 1000 (best 1000)
[0:02:40.661228644] [1140] DEBUG RPI pipeline_base.cpp:974 Format: 1280x720 fmt SRGGB12 Score: 2000 (best 1000)
[0:02:40.661237033] [1140] DEBUG RPI pipeline_base.cpp:974 Format: 1920x1080 fmt SRGGB12 Score: 0 (best 0)
[0:02:40.661256552] [1140] DEBUG Camera camera.cpp:1140 streams configuration: (0) 800x600-XRGB8888 (1) 1920x1080-SRGGB12_CSI2P
Mode selection for 960:540:12:P
    SRGGB10_CSI2P,1280x720/0 - Score: 1125
    SRGGB10_CSI2P,1920x1080/0 - Score: 1375
    SRGGB12_CSI2P,1280x720/0 - Score: 125
    SRGGB12_CSI2P,1920x1080/0 - Score: 375
[0:02:40.661343519] [1140] DEBUG RPI pipeline_base.cpp:974 Format: 1280x720 fmt SRGGB10 Score: 1000 (best 1000)
[0:02:40.661353334] [1140] DEBUG RPI pipeline_base.cpp:974 Format: 1920x1080 fmt SRGGB10 Score: 1250 (best 1000)
[0:02:40.661362538] [1140] DEBUG RPI pipeline_base.cpp:974 Format: 1280x720 fmt SRGGB12 Score: 0 (best 0)
[0:02:40.661370705] [1140] DEBUG RPI pipeline_base.cpp:974 Format: 1920x1080 fmt SRGGB12 Score: 250 (best 0)
[0:02:40.661389224] [1140] DEBUG RPI pisp.cpp:1276 minSize: width 20 height 12
[0:02:40.661398502] [1140] DEBUG RPI pisp.cpp:1320 For stream 960x540-YU12 swDownscale is 1
[0:02:40.661411873] [1140] DEBUG RPI pipeline_base.cpp:286 Try color space sYCC
Stream configuration adjusted
[0:02:40.661430448] [1140] DEBUG RPI pipeline_base.cpp:974 Format: 1280x720 fmt SRGGB10 Score: 1000 (best 1000)
[0:02:40.661439782] [1140] DEBUG RPI pipeline_base.cpp:974 Format: 1920x1080 fmt SRGGB10 Score: 1250 (best 1000)
[0:02:40.661448875] [1140] DEBUG RPI pipeline_base.cpp:974 Format: 1280x720 fmt SRGGB12 Score: 0 (best 0)
[0:02:40.661457116] [1140] DEBUG RPI pipeline_base.cpp:974 Format: 1920x1080 fmt SRGGB12 Score: 250 (best 0)
[0:02:40.661468209] [1140] DEBUG RPI pisp.cpp:1276 minSize: width 20 height 12
[0:02:40.661475672] [1140] DEBUG RPI pisp.cpp:1320 For stream 960x540-YU12 swDownscale is 1
[0:02:40.661484210] [1140] DEBUG RPI pipeline_base.cpp:286 Try color space sYCC
[0:02:40.661496951] [1140]  INFO Camera camera.cpp:1205 configuring streams: (0) 960x540-YUV420 (1) 1280x720-RGGB_PISP_COMP1
[0:02:40.661584139] [1145]  INFO RPI pisp.cpp:1483 Sensor: /base/axi/pcie@1000120000/rp1/i2c@88000/imx290@1a - Selected sensor format: 1280x720-SRGGB12_1X12 - Selected CFE format: 1280x720-PC1R
[0:02:40.661609159] [1145] DEBUG RPI pisp.cpp:1541 Setting ISP Output1 to 960x540-YU12 (sw downscale 1)
[0:02:40.661625956] [1145] DEBUG RPI pisp.cpp:1547 After setFormat, stride 1024
[0:02:40.661639308] [1145] DEBUG RPI pisp.cpp:1557 Stream ISP Output1 has color space sYCC
[0:02:40.661654402] [1145] DEBUG RPI pisp.cpp:2158 Output 1 (0, 0)/1280x720
[0:02:40.661684292] [1145] DEBUG MediaDevice media_device.cpp:827 /dev/media2[rp1-cfe]: 'csi2'[4] -> 'rp1-cfe-csi2_ch0'[0]: 0
[0:02:40.661702774] [1145] DEBUG MediaDevice media_device.cpp:827 /dev/media2[rp1-cfe]: 'csi2'[4] -> 'pisp-fe'[0]: 1
[0:02:40.661718812] [1145] DEBUG MediaDevice media_device.cpp:827 /dev/media2[rp1-cfe]: 'csi2'[5] -> 'rp1-cfe-embedded'[0]: 0
[0:02:40.661735405] [1145] DEBUG MediaDevice media_device.cpp:827 /dev/media2[rp1-cfe]: 'rp1-cfe-fe_config'[0] -> 'pisp-fe'[1]: 1
[0:02:40.661753461] [1145] DEBUG MediaDevice media_device.cpp:827 /dev/media2[rp1-cfe]: 'pisp-fe'[2] -> 'rp1-cfe-fe_image0'[0]: 1
[0:02:40.661768703] [1145] DEBUG MediaDevice media_device.cpp:827 /dev/media2[rp1-cfe]: 'pisp-fe'[3] -> 'rp1-cfe-fe_image1'[0]: 0
[0:02:40.661784666] [1145] DEBUG MediaDevice media_device.cpp:827 /dev/media2[rp1-cfe]: 'pisp-fe'[4] -> 'rp1-cfe-fe_stats'[0]: 1
[0:02:40.661873873] [1145] DEBUG IPARPI ipa_base.cpp:1673 setting sync frame duration to  115685382.91us
[0:02:40.661906486] [1145] DEBUG IPARPI ipa_base.cpp:1698 Applying AGC Exposure: 20000.00us (Exposure lines: 900, AGC requested 20000.00us) Gain: 1 (Gain Code: 0)
[0:02:40.662152922] [1140] DEBUG Buffer framebuffer.cpp:351 Buffer is contiguous
[0:02:40.662311558] [1140] DEBUG Buffer framebuffer.cpp:351 Buffer is contiguous
[0:02:40.662444434] [1140] DEBUG Buffer framebuffer.cpp:351 Buffer is contiguous
[0:02:40.662586810] [1140] DEBUG Buffer framebuffer.cpp:351 Buffer is contiguous
[0:02:40.662766113] [1140] DEBUG Buffer framebuffer.cpp:351 Buffer is contiguous
[0:02:40.662943010] [1140] DEBUG Buffer framebuffer.cpp:351 Buffer is contiguous
[0:02:40.663118739] [1140] DEBUG Buffer framebuffer.cpp:351 Buffer is contiguous
[0:02:40.663307302] [1140] DEBUG Buffer framebuffer.cpp:351 Buffer is contiguous
[0:02:40.663450678] [1140] DEBUG Request request.cpp:369 Created request - cookie: 0
[0:02:40.663482865] [1140] DEBUG Request request.cpp:369 Created request - cookie: 0
[0:02:40.663499162] [1140] DEBUG Request request.cpp:369 Created request - cookie: 0
[0:02:40.663516311] [1140] DEBUG Request request.cpp:369 Created request - cookie: 0
[0:02:40.663560238] [1140] DEBUG Camera camera.cpp:1382 Starting capture
[0:02:40.663711207] [1149] DEBUG IPARPI ipa_base.cpp:826 Request ctrl: Sharpness = 1.000000
[0:02:40.663746116] [1149] DEBUG IPARPI ipa_base.cpp:826 Request ctrl: Contrast = 1.000000
[0:02:40.663763191] [1149] DEBUG IPARPI ipa_base.cpp:826 Request ctrl: Brightness = 0.000000
[0:02:40.663780321] [1149] DEBUG IPARPI ipa_base.cpp:826 Request ctrl: ExposureValue = 0.000000
[0:02:40.663797081] [1149] DEBUG RPiAgc agc.cpp:157 setEv 1 for channel 0
[0:02:40.663814804] [1149] DEBUG IPARPI ipa_base.cpp:826 Request ctrl: AeMeteringMode = 0
[0:02:40.663831564] [1149] DEBUG IPARPI ipa_base.cpp:826 Request ctrl: FrameDurationLimits = [ 33333, 33333 ]
[0:02:40.663852565] [1149] DEBUG IPARPI ipa_base.cpp:1673 setting sync frame duration to  33311.11us
[0:02:40.663876788] [1149] DEBUG IPARPI ipa_base.cpp:826 Request ctrl: Saturation = 1.000000
[0:02:40.663893585] [1149] DEBUG IPARPI ipa_base.cpp:826 Request ctrl: ScalerCrops = [ (320, 180)/1280x720 ]
[0:02:40.663913475] [1149] DEBUG IPARPI ipa_base.cpp:826 Request ctrl: AwbMode = 0
[0:02:40.663928438] [1149] DEBUG IPARPI ipa_base.cpp:826 Request ctrl: AeExposureMode = 0
[0:02:40.663943384] [1149] DEBUG RPiAgc agc.cpp:97 autoExposureEnabled
[0:02:40.663958014] [1149] DEBUG IPARPI ipa_base.cpp:826 Request ctrl: NoiseReductionMode = 3
[0:02:40.663982107] [1149] DEBUG RPiAgc agc.cpp:259 switchMode for channel 0
[0:02:40.663996682] [1149] DEBUG RPiAgc agc_channel.cpp:615 ev 1 fixedExposureTime 0.00us fixedAnalogueGain 0
[0:02:40.664045740] [1149] DEBUG RPiAgc agc_channel.cpp:652 exposureMode normal constraintMode normal meteringMode centre-weighted
[0:02:40.664061425] [1149] DEBUG RPiAgc agc_channel.cpp:1015 Output written, total exposure requested is 0.00us
[0:02:40.664077500] [1149] DEBUG RPiAgc agc_channel.cpp:1017 Camera exposure update: exposure time 1000.00us analogue gain 1
[0:02:40.664099779] [1149] DEBUG RPiAlsc alsc.cpp:336 AWB results found, using 4500
[0:02:40.664126002] [1149] DEBUG RPiAlsc alsc.cpp:464 no calibrations found
[0:02:40.664145392] [1149] DEBUG RPiAlsc alsc.cpp:464 no calibrations found
[0:02:40.664196338] [1149] DEBUG IPARPI ipa_base.cpp:1698 Applying AGC Exposure: 1000.00us (Exposure lines: 45, AGC requested 1000.00us) Gain: 1 (Gain Code: 0)
[0:02:40.664226191] [1149] DEBUG IPARPI ipa_base.cpp:363 Drop 7 frames on startup
[0:02:40.664275138] [1145] DEBUG RPI pisp.cpp:1020 Preparing 2 buffers for stream CFE Image
[0:02:40.665070929] [1145] DEBUG V4L2 v4l2_videodevice.cpp:1334 /dev/video4[16:cap]: 3 buffers requested.
[0:02:40.665106542] [1145] DEBUG Buffer framebuffer.cpp:351 Buffer is contiguous
[0:02:40.665127654] [1145] DEBUG Buffer framebuffer.cpp:351 Buffer is contiguous
[0:02:40.665207176] [1145] DEBUG V4L2 v4l2_videodevice.cpp:1334 /dev/video4[16:cap]: 0 buffers requested.
[0:02:40.665279160] [1145] DEBUG V4L2 v4l2_videodevice.cpp:1334 /dev/video4[16:cap]: 32 buffers requested.
[0:02:40.665303143] [1145] DEBUG V4L2 v4l2_videodevice.cpp:1601 /dev/video4[16:cap]: Prepared to import 32 buffers
[0:02:40.665317680] [1145] DEBUG RPI pisp.cpp:1020 Preparing 12 buffers for stream CFE Config
[0:02:40.665894870] [1145] DEBUG V4L2 v4l2_videodevice.cpp:1334 /dev/video7[17:out]: 12 buffers requested.
[0:02:40.665917353] [1145] DEBUG Buffer framebuffer.cpp:351 Buffer is contiguous
[0:02:40.665936798] [1145] DEBUG Buffer framebuffer.cpp:351 Buffer is contiguous
[0:02:40.665956854] [1145] DEBUG Buffer framebuffer.cpp:351 Buffer is contiguous
[0:02:40.665975114] [1145] DEBUG Buffer framebuffer.cpp:351 Buffer is contiguous
[0:02:40.665993856] [1145] DEBUG Buffer framebuffer.cpp:351 Buffer is contiguous
[0:02:40.666012264] [1145] DEBUG Buffer framebuffer.cpp:351 Buffer is contiguous
[0:02:40.666032894] [1145] DEBUG Buffer framebuffer.cpp:351 Buffer is contiguous
[0:02:40.666052154] [1145] DEBUG Buffer framebuffer.cpp:351 Buffer is contiguous
[0:02:40.666069692] [1145] DEBUG Buffer framebuffer.cpp:351 Buffer is contiguous
[0:02:40.666088971] [1145] DEBUG Buffer framebuffer.cpp:351 Buffer is contiguous
[0:02:40.666116009] [1145] DEBUG Buffer framebuffer.cpp:351 Buffer is contiguous
[0:02:40.666134436] [1145] DEBUG Buffer framebuffer.cpp:351 Buffer is contiguous
[0:02:40.666152659] [1145] DEBUG V4L2 v4l2_videodevice.cpp:1334 /dev/video7[17:out]: 0 buffers requested.
[0:02:40.666229180] [1145] DEBUG V4L2 v4l2_videodevice.cpp:1334 /dev/video7[17:out]: 32 buffers requested.
[0:02:40.666246366] [1145] DEBUG V4L2 v4l2_videodevice.cpp:1601 /dev/video7[17:out]: Prepared to import 32 buffers
[0:02:40.666260589] [1145] DEBUG RPI pisp.cpp:1020 Preparing 12 buffers for stream CFE Stats
[0:02:40.666877169] [1145] DEBUG V4L2 v4l2_videodevice.cpp:1334 /dev/video6[18:cap]: 12 buffers requested.
[0:02:40.666898948] [1145] DEBUG Buffer framebuffer.cpp:351 Buffer is contiguous
[0:02:40.666917541] [1145] DEBUG Buffer framebuffer.cpp:351 Buffer is contiguous
[0:02:40.666935487] [1145] DEBUG Buffer framebuffer.cpp:351 Buffer is contiguous
[0:02:40.666953858] [1145] DEBUG Buffer framebuffer.cpp:351 Buffer is contiguous
[0:02:40.666972803] [1145] DEBUG Buffer framebuffer.cpp:351 Buffer is contiguous
[0:02:40.666991193] [1145] DEBUG Buffer framebuffer.cpp:351 Buffer is contiguous
[0:02:40.667009601] [1145] DEBUG Buffer framebuffer.cpp:351 Buffer is contiguous
[0:02:40.667029972] [1145] DEBUG Buffer framebuffer.cpp:351 Buffer is contiguous
[0:02:40.667047825] [1145] DEBUG Buffer framebuffer.cpp:351 Buffer is contiguous
[0:02:40.667069344] [1145] DEBUG Buffer framebuffer.cpp:351 Buffer is contiguous
[0:02:40.667088419] [1145] DEBUG Buffer framebuffer.cpp:351 Buffer is contiguous
[0:02:40.667106512] [1145] DEBUG Buffer framebuffer.cpp:351 Buffer is contiguous
[0:02:40.667123365] [1145] DEBUG V4L2 v4l2_videodevice.cpp:1334 /dev/video6[18:cap]: 0 buffers requested.
[0:02:40.667152070] [1145] DEBUG V4L2 v4l2_videodevice.cpp:1334 /dev/video6[18:cap]: 32 buffers requested.
[0:02:40.667167626] [1145] DEBUG V4L2 v4l2_videodevice.cpp:1601 /dev/video6[18:cap]: Prepared to import 32 buffers
[0:02:40.667182015] [1145] DEBUG RPI pisp.cpp:1020 Preparing 6 buffers for stream ISP Input
[0:02:40.667210776] [1145] DEBUG V4L2 v4l2_videodevice.cpp:1334 /dev/video20[19:out]: 32 buffers requested.
[0:02:40.667226091] [1145] DEBUG V4L2 v4l2_videodevice.cpp:1601 /dev/video20[19:out]: Prepared to import 32 buffers
[0:02:40.667240481] [1145] DEBUG RPI pisp.cpp:1020 Preparing 2 buffers for stream ISP Config
[0:02:40.667360319] [1145] DEBUG V4L2 v4l2_videodevice.cpp:1334 /dev/video27[22:out]: 2 buffers requested.
[0:02:40.667382431] [1145] DEBUG Buffer framebuffer.cpp:351 Buffer is contiguous
[0:02:40.667400820] [1145] DEBUG Buffer framebuffer.cpp:351 Buffer is contiguous
[0:02:40.667418136] [1145] DEBUG V4L2 v4l2_videodevice.cpp:1334 /dev/video27[22:out]: 0 buffers requested.
[0:02:40.667464564] [1145] DEBUG V4L2 v4l2_videodevice.cpp:1334 /dev/video27[22:out]: 32 buffers requested.
[0:02:40.667482064] [1145] DEBUG V4L2 v4l2_videodevice.cpp:1601 /dev/video27[22:out]: Prepared to import 32 buffers
[0:02:40.667496491] [1145] DEBUG RPI pisp.cpp:1020 Preparing 2 buffers for stream ISP TDN Input
[0:02:40.667525455] [1145] DEBUG V4L2 v4l2_videodevice.cpp:1334 /dev/video21[23:out]: 32 buffers requested.
[0:02:40.667540900] [1145] DEBUG V4L2 v4l2_videodevice.cpp:1601 /dev/video21[23:out]: Prepared to import 32 buffers
[0:02:40.667555456] [1145] DEBUG RPI pisp.cpp:1020 Preparing 2 buffers for stream ISP TDN Output
[0:02:40.668036309] [1145] DEBUG V4L2 v4l2_videodevice.cpp:1334 /dev/video25[24:cap]: 2 buffers requested.
[0:02:40.668061829] [1145] DEBUG Buffer framebuffer.cpp:351 Buffer is contiguous
[0:02:40.668081311] [1145] DEBUG Buffer framebuffer.cpp:351 Buffer is contiguous
[0:02:40.668098849] [1145] DEBUG V4L2 v4l2_videodevice.cpp:1334 /dev/video25[24:cap]: 0 buffers requested.
[0:02:40.668129146] [1145] DEBUG V4L2 v4l2_videodevice.cpp:1334 /dev/video25[24:cap]: 32 buffers requested.
[0:02:40.668144925] [1145] DEBUG V4L2 v4l2_videodevice.cpp:1601 /dev/video25[24:cap]: Prepared to import 32 buffers
[0:02:40.668159536] [1145] DEBUG RPI pisp.cpp:1020 Preparing 2 buffers for stream ISP Stitch Input
[0:02:40.668187297] [1145] DEBUG V4L2 v4l2_videodevice.cpp:1334 /dev/video22[25:out]: 32 buffers requested.
[0:02:40.668202427] [1145] DEBUG V4L2 v4l2_videodevice.cpp:1601 /dev/video22[25:out]: Prepared to import 32 buffers
[0:02:40.668216761] [1145] DEBUG RPI pisp.cpp:1020 Preparing 2 buffers for stream ISP Stitch Output
[0:02:40.668672076] [1145] DEBUG V4L2 v4l2_videodevice.cpp:1334 /dev/video26[26:cap]: 2 buffers requested.
[0:02:40.668693688] [1145] DEBUG Buffer framebuffer.cpp:351 Buffer is contiguous
[0:02:40.668715226] [1145] DEBUG Buffer framebuffer.cpp:351 Buffer is contiguous
[0:02:40.668732819] [1145] DEBUG V4L2 v4l2_videodevice.cpp:1334 /dev/video26[26:cap]: 0 buffers requested.
[0:02:40.668761320] [1145] DEBUG V4L2 v4l2_videodevice.cpp:1334 /dev/video26[26:cap]: 32 buffers requested.
[0:02:40.668776932] [1145] DEBUG V4L2 v4l2_videodevice.cpp:1601 /dev/video26[26:cap]: Prepared to import 32 buffers
[0:02:40.668791599] [1145] DEBUG RPI pisp.cpp:1020 Preparing 2 buffers for stream ISP Output1
[0:02:40.669208116] [1145] DEBUG V4L2 v4l2_videodevice.cpp:1334 /dev/video24[21:cap]: 2 buffers requested.
[0:02:40.669231339] [1145] DEBUG Buffer framebuffer.cpp:351 Buffer is contiguous
[0:02:40.669251266] [1145] DEBUG Buffer framebuffer.cpp:351 Buffer is contiguous
[0:02:40.669267896] [1145] DEBUG V4L2 v4l2_videodevice.cpp:1334 /dev/video24[21:cap]: 0 buffers requested.
[0:02:40.669325176] [1145] DEBUG V4L2 v4l2_videodevice.cpp:1334 /dev/video24[21:cap]: 32 buffers requested.
[0:02:40.669342529] [1145] DEBUG V4L2 v4l2_videodevice.cpp:1601 /dev/video24[21:cap]: Prepared to import 32 buffers
[0:02:40.669366123] [1145] DEBUG Buffer framebuffer.cpp:351 Buffer is contiguous
[0:02:40.669389012] [1145] DEBUG Buffer framebuffer.cpp:351 Buffer is contiguous
[0:02:40.669409106] [1145] DEBUG Buffer framebuffer.cpp:351 Buffer is contiguous
[0:02:40.669434107] [1145] DEBUG Buffer framebuffer.cpp:351 Buffer is contiguous
[0:02:40.669453811] [1145] DEBUG Buffer framebuffer.cpp:351 Buffer is contiguous
[0:02:40.669473145] [1145] DEBUG Buffer framebuffer.cpp:351 Buffer is contiguous
[0:02:40.669496239] [1145] DEBUG Buffer framebuffer.cpp:351 Buffer is contiguous
[0:02:40.669515592] [1145] DEBUG Buffer framebuffer.cpp:351 Buffer is contiguous
[0:02:40.669535111] [1145] DEBUG Buffer framebuffer.cpp:351 Buffer is contiguous
[0:02:40.669554704] [1145] DEBUG Buffer framebuffer.cpp:351 Buffer is contiguous
[0:02:40.669579224] [1145] DEBUG Buffer framebuffer.cpp:351 Buffer is contiguous
[0:02:40.669599465] [1145] DEBUG Buffer framebuffer.cpp:351 Buffer is contiguous
[0:02:40.669622874] [1145] DEBUG RPISTREAM rpi_stream.cpp:271 Queuing buffer 1 for CFE Image
[0:02:40.669641189] [1145] DEBUG V4L2 v4l2_videodevice.cpp:2011 /dev/video4[16:cap]: Queueing buffer 0
[0:02:40.669719600] [1145] DEBUG RPISTREAM rpi_stream.cpp:271 Queuing buffer 2 for CFE Image
[0:02:40.669735563] [1145] DEBUG V4L2 v4l2_videodevice.cpp:2011 /dev/video4[16:cap]: Queueing buffer 1
[0:02:40.669804085] [1145] DEBUG RPISTREAM rpi_stream.cpp:136 No buffers available for CFE Image
[0:02:40.669818456] [1145] DEBUG RPISTREAM rpi_stream.cpp:136 No buffers available for CFE Image
[0:02:40.669832938] [1145] DEBUG RPISTREAM rpi_stream.cpp:136 No buffers available for CFE Image
[0:02:40.669846012] [1145] DEBUG RPISTREAM rpi_stream.cpp:136 No buffers available for CFE Image
[0:02:40.669859309] [1145] DEBUG RPISTREAM rpi_stream.cpp:136 No buffers available for CFE Image
[0:02:40.669872032] [1145] DEBUG RPISTREAM rpi_stream.cpp:271 Queuing buffer 1 for CFE Stats
[0:02:40.669887199] [1145] DEBUG V4L2 v4l2_videodevice.cpp:2011 /dev/video6[18:cap]: Queueing buffer 0
[0:02:40.669947942] [1145] DEBUG RPISTREAM rpi_stream.cpp:271 Queuing buffer 2 for CFE Stats
[0:02:40.669962795] [1145] DEBUG V4L2 v4l2_videodevice.cpp:2011 /dev/video6[18:cap]: Queueing buffer 1
[0:02:40.670022242] [1145] DEBUG RPISTREAM rpi_stream.cpp:271 Queuing buffer 3 for CFE Stats
[0:02:40.670036983] [1145] DEBUG V4L2 v4l2_videodevice.cpp:2011 /dev/video6[18:cap]: Queueing buffer 2
[0:02:40.670097078] [1145] DEBUG RPISTREAM rpi_stream.cpp:271 Queuing buffer 4 for CFE Stats
[0:02:40.670111931] [1145] DEBUG V4L2 v4l2_videodevice.cpp:2011 /dev/video6[18:cap]: Queueing buffer 3
[0:02:40.670171266] [1145] DEBUG RPISTREAM rpi_stream.cpp:271 Queuing buffer 5 for CFE Stats
[0:02:40.670185971] [1145] DEBUG V4L2 v4l2_videodevice.cpp:2011 /dev/video6[18:cap]: Queueing buffer 4
[0:02:40.670246029] [1145] DEBUG RPISTREAM rpi_stream.cpp:271 Queuing buffer 6 for CFE Stats
[0:02:40.670261381] [1145] DEBUG V4L2 v4l2_videodevice.cpp:2011 /dev/video6[18:cap]: Queueing buffer 5
[0:02:40.670320921] [1145] DEBUG RPISTREAM rpi_stream.cpp:271 Queuing buffer 7 for CFE Stats
[0:02:40.670335588] [1145] DEBUG V4L2 v4l2_videodevice.cpp:2011 /dev/video6[18:cap]: Queueing buffer 6
[0:02:40.670396164] [1145] DEBUG RPISTREAM rpi_stream.cpp:271 Queuing buffer 8 for CFE Stats
[0:02:40.670410998] [1145] DEBUG V4L2 v4l2_videodevice.cpp:2011 /dev/video6[18:cap]: Queueing buffer 7
[0:02:40.670472871] [1145] DEBUG RPISTREAM rpi_stream.cpp:271 Queuing buffer 9 for CFE Stats
[0:02:40.670487631] [1145] DEBUG V4L2 v4l2_videodevice.cpp:2011 /dev/video6[18:cap]: Queueing buffer 8
[0:02:40.670548096] [1145] DEBUG RPISTREAM rpi_stream.cpp:271 Queuing buffer 10 for CFE Stats
[0:02:40.670562560] [1145] DEBUG V4L2 v4l2_videodevice.cpp:2011 /dev/video6[18:cap]: Queueing buffer 9
[0:02:40.670621822] [1145] DEBUG RPISTREAM rpi_stream.cpp:271 Queuing buffer 11 for CFE Stats
[0:02:40.670637156] [1145] DEBUG V4L2 v4l2_videodevice.cpp:2011 /dev/video6[18:cap]: Queueing buffer 10
[0:02:40.670699325] [1145] DEBUG RPISTREAM rpi_stream.cpp:271 Queuing buffer 12 for CFE Stats
[0:02:40.670714048] [1145] DEBUG V4L2 v4l2_videodevice.cpp:2011 /dev/video6[18:cap]: Queueing buffer 11
[0:02:40.670773328] [1145] DEBUG RPISTREAM rpi_stream.cpp:271 Queuing buffer 1 for ISP Output1
[0:02:40.670788643] [1145] DEBUG V4L2 v4l2_videodevice.cpp:2011 /dev/video24[21:cap]: Queueing buffer 0
[0:02:40.670857276] [1145] DEBUG RPISTREAM rpi_stream.cpp:271 Queuing buffer 2 for ISP Output1
[0:02:40.670872443] [1145] DEBUG V4L2 v4l2_videodevice.cpp:2011 /dev/video24[21:cap]: Queueing buffer 1
[0:02:40.670939927] [1145] DEBUG RPISTREAM rpi_stream.cpp:136 No buffers available for ISP Output1
[0:02:40.670954076] [1145] DEBUG RPISTREAM rpi_stream.cpp:136 No buffers available for ISP Output1
[0:02:40.670968558] [1145] DEBUG RPISTREAM rpi_stream.cpp:136 No buffers available for ISP Output1
[0:02:40.670982077] [1145] DEBUG RPISTREAM rpi_stream.cpp:136 No buffers available for ISP Output1
[0:02:40.670995485] [1145] DEBUG RPISTREAM rpi_stream.cpp:136 No buffers available for ISP Output1
[0:02:40.671009319] [1145] DEBUG ClockRec clock_recovery.cpp:111 addSample
[0:02:40.671023282] [1145] DEBUG ClockRec clock_recovery.cpp:141 addSample 160671022 1752176933258679
[0:02:40.671036913] [1145] DEBUG ClockRec clock_recovery.cpp:225 getOutput 160671022 1752176933258679
[0:02:40.671080063] [1145] DEBUG RPISTREAM rpi_stream.cpp:271 Queuing buffer 1 for CFE Config
[0:02:40.671096878] [1145] DEBUG V4L2 v4l2_videodevice.cpp:2011 /dev/video7[17:out]: Queueing buffer 0
[0:02:40.671160455] [1145] DEBUG RPISTREAM rpi_stream.cpp:271 Queuing buffer 2 for CFE Config
[0:02:40.671176048] [1145] DEBUG V4L2 v4l2_videodevice.cpp:2011 /dev/video7[17:out]: Queueing buffer 1
[0:02:40.900493852] [1145] DEBUG RPI pisp.cpp:1857 Setting CFE timeout to 1000000.00us
[0:02:40.900536761] [1145] DEBUG Timer timer.cpp:93 Starting timer 0x7ffec80434d8: deadline 0:02:41.900533890
[0:02:40.900550650] [1145] DEBUG Event event_dispatcher_poll.cpp:215 next timer 0x7ffec80434d8 expires in 0.999984573
[0:02:40.900574021] [1145] DEBUG Event event_dispatcher_poll.cpp:215 next timer 0x7ffec80434d8 expires in 0.999960794
[0:02:40.900595393] [1145] DEBUG RPI pipeline_base.cpp:748 queueRequestDevice: New request sequence: 0
[0:02:40.900642191] [1145] DEBUG RPI pipeline_base.cpp:748 queueRequestDevice: New request sequence: 1
[0:02:40.900679211] [1145] DEBUG RPI pipeline_base.cpp:748 queueRequestDevice: New request sequence: 2
[0:02:40.900722176] [1145] DEBUG RPI pipeline_base.cpp:748 queueRequestDevice: New request sequence: 3
[0:02:40.900765492] [1145] DEBUG Event event_dispatcher_poll.cpp:215 next timer 0x7ffec80434d8 expires in 0.999769379
[0:02:41.901575538] [1145]  WARN V4L2 v4l2_videodevice.cpp:2150 /dev/video4[16:cap]: Dequeue timer of 1000000.00us has expired!
[0:02:41.901610688] [1145] ERROR RPI pipeline_base.cpp:1358 Camera frontend has timed out!
[0:02:41.901625725] [1145] ERROR RPI pipeline_base.cpp:1359 Please check that your camera sensor connector is attached securely.
[0:02:41.901640485] [1145] ERROR RPI pipeline_base.cpp:1360 Alternatively, try another cable and/or sensor.
[0:02:41.940472839] [1145] DEBUG Request request.cpp:129 Request(0:X:0/2:0)
[0:02:41.940504192] [1145] DEBUG Request request.cpp:129 Request(1:X:0/2:0)
ERROR: Device timeout detected, attempting a restart!!![0:02:41.940514471] [1145] DEBUG Request request.cpp:129 Request(2:X:0/2:0)
[0:02:41.940527360] [1145] DEBUG Request request.cpp:129 Request(3:X:0/2:0)

[0:02:41.940550380] [1140] DEBUG Camera camera.cpp:1426 Stopping capture
[0:02:41.940751499] [1140] DEBUG Request request.cpp:369 Created request - cookie: 0
[0:02:41.940776185] [1140] DEBUG Request request.cpp:369 Created request - cookie: 0
[0:02:41.940792000] [1140] DEBUG Request request.cpp:369 Created request - cookie: 0
[0:02:41.940810056] [1140] DEBUG Request request.cpp:369 Created request - cookie: 0
[0:02:41.940835261] [1140] DEBUG Camera camera.cpp:1382 Starting capture
[0:02:41.940914468] [1151] DEBUG IPARPI ipa_base.cpp:826 Request ctrl: Sharpness = 1.000000
[0:02:41.940945951] [1151] DEBUG IPARPI ipa_base.cpp:826 Request ctrl: Contrast = 1.000000
[0:02:41.940964211] [1151] DEBUG IPARPI ipa_base.cpp:826 Request ctrl: Brightness = 0.000000
[0:02:41.940982100] [1151] DEBUG IPARPI ipa_base.cpp:826 Request ctrl: ExposureValue = 0.000000
[0:02:41.940999879] [1151] DEBUG RPiAgc agc.cpp:157 setEv 1 for channel 0
[0:02:41.941018324] [1151] DEBUG IPARPI ipa_base.cpp:826 Request ctrl: AwbMode = 0
[0:02:41.941035602] [1151] DEBUG IPARPI ipa_base.cpp:826 Request ctrl: AeExposureMode = 0
[0:02:41.941051159] [1151] DEBUG RPiAgc agc.cpp:97 autoExposureEnabled
[0:02:41.941065696] [1151] DEBUG IPARPI ipa_base.cpp:826 Request ctrl: AeMeteringMode = 0
[0:02:41.941082364] [1151] DEBUG IPARPI ipa_base.cpp:826 Request ctrl: FrameDurationLimits = [ 33333, 33333 ]
[0:02:41.941105605] [1151] DEBUG IPARPI ipa_base.cpp:1673 setting sync frame duration to  33311.11us
[0:02:41.941132051] [1151] DEBUG IPARPI ipa_base.cpp:826 Request ctrl: Saturation = 1.000000
[0:02:41.941148625] [1151] DEBUG IPARPI ipa_base.cpp:826 Request ctrl: ScalerCrops = [ (320, 180)/1280x720 ]
[0:02:41.941176497] [1151] DEBUG RPiAgc agc.cpp:259 switchMode for channel 0
[0:02:41.941191646] [1151] DEBUG RPiAgc agc_channel.cpp:615 ev 1 fixedExposureTime 0.00us fixedAnalogueGain 0
[0:02:41.941211943] [1151] DEBUG RPiAgc agc_channel.cpp:652 exposureMode normal constraintMode normal meteringMode centre-weighted
[0:02:41.941228518] [1151] DEBUG RPiAgc agc_channel.cpp:1015 Output written, total exposure requested is 0.00us
[0:02:41.941246537] [1151] DEBUG RPiAgc agc_channel.cpp:1017 Camera exposure update: exposure time 1000.00us analogue gain 1
[0:02:41.941268964] [1151] DEBUG RPiAlsc alsc.cpp:336 AWB results found, using 4500
[0:02:41.941300224] [1151] DEBUG IPARPI ipa_base.cpp:1698 Applying AGC Exposure: 1000.00us (Exposure lines: 45, AGC requested 1000.00us) Gain: 1 (Gain Code: 0)
[0:02:41.941363986] [1145] DEBUG RPISTREAM rpi_stream.cpp:271 Queuing buffer 1 for CFE Stats
[0:02:41.941392987] [1145] DEBUG V4L2 v4l2_videodevice.cpp:2011 /dev/video6[18:cap]: Queueing buffer 0
[0:02:41.941417432] [1145] DEBUG RPISTREAM rpi_stream.cpp:271 Queuing buffer 2 for CFE Stats
[0:02:41.941434896] [1145] DEBUG V4L2 v4l2_videodevice.cpp:2011 /dev/video6[18:cap]: Queueing buffer 1
[0:02:41.941451286] [1145] DEBUG RPISTREAM rpi_stream.cpp:271 Queuing buffer 3 for CFE Stats
[0:02:41.941467768] [1145] DEBUG V4L2 v4l2_videodevice.cpp:2011 /dev/video6[18:cap]: Queueing buffer 2
[0:02:41.941484731] [1145] DEBUG RPISTREAM rpi_stream.cpp:271 Queuing buffer 4 for CFE Stats
[0:02:41.941500547] [1145] DEBUG V4L2 v4l2_videodevice.cpp:2011 /dev/video6[18:cap]: Queueing buffer 3
[0:02:41.941517159] [1145] DEBUG RPISTREAM rpi_stream.cpp:271 Queuing buffer 5 for CFE Stats
[0:02:41.941533048] [1145] DEBUG V4L2 v4l2_videodevice.cpp:2011 /dev/video6[18:cap]: Queueing buffer 4
[0:02:41.941548975] [1145] DEBUG RPISTREAM rpi_stream.cpp:271 Queuing buffer 6 for CFE Stats
[0:02:41.941564679] [1145] DEBUG V4L2 v4l2_videodevice.cpp:2011 /dev/video6[18:cap]: Queueing buffer 5
[0:02:41.941581957] [1145] DEBUG RPISTREAM rpi_stream.cpp:271 Queuing buffer 7 for CFE Stats
[0:02:41.941596421] [1145] DEBUG V4L2 v4l2_videodevice.cpp:2011 /dev/video6[18:cap]: Queueing buffer 6
[0:02:41.941614125] [1145] DEBUG RPISTREAM rpi_stream.cpp:271 Queuing buffer 8 for CFE Stats
[0:02:41.941628570] [1145] DEBUG V4L2 v4l2_videodevice.cpp:2011 /dev/video6[18:cap]: Queueing buffer 7
[0:02:41.941644886] [1145] DEBUG RPISTREAM rpi_stream.cpp:271 Queuing buffer 9 for CFE Stats
[0:02:41.941652960] [1145] DEBUG V4L2 v4l2_videodevice.cpp:2011 /dev/video6[18:cap]: Queueing buffer 8
[0:02:41.941661424] [1145] DEBUG RPISTREAM rpi_stream.cpp:271 Queuing buffer 10 for CFE Stats
[0:02:41.941668776] [1145] DEBUG V4L2 v4l2_videodevice.cpp:2011 /dev/video6[18:cap]: Queueing buffer 9
[0:02:41.941677109] [1145] DEBUG RPISTREAM rpi_stream.cpp:271 Queuing buffer 11 for CFE Stats
[0:02:41.941684406] [1145] DEBUG V4L2 v4l2_videodevice.cpp:2011 /dev/video6[18:cap]: Queueing buffer 10
[0:02:41.941692721] [1145] DEBUG RPISTREAM rpi_stream.cpp:271 Queuing buffer 12 for CFE Stats
[0:02:41.941700055] [1145] DEBUG V4L2 v4l2_videodevice.cpp:2011 /dev/video6[18:cap]: Queueing buffer 11
[0:02:41.941709092] [1145] DEBUG ClockRec clock_recovery.cpp:111 addSample
[0:02:41.941716111] [1145] DEBUG ClockRec clock_recovery.cpp:141 addSample 161941714 1752176934529371
[0:02:41.941723574] [1145] DEBUG ClockRec clock_recovery.cpp:225 getOutput 161941714 1752176934529371
[0:02:41.941730371] [1145] DEBUG ClockRec clock_recovery.cpp:225 getOutput 160671022 1752176933258679
[0:02:41.941737019] [1145] DEBUG ClockRec clock_recovery.cpp:225 getOutput 161941714 1752176934529371
[0:02:41.941762891] [1145] DEBUG RPISTREAM rpi_stream.cpp:271 Queuing buffer 1 for CFE Config
[0:02:41.941772021] [1145] DEBUG V4L2 v4l2_videodevice.cpp:2011 /dev/video7[17:out]: Queueing buffer 0
[0:02:41.941783891] [1145] DEBUG RPISTREAM rpi_stream.cpp:271 Queuing buffer 2 for CFE Config
[0:02:41.941791595] [1145] DEBUG V4L2 v4l2_videodevice.cpp:2011 /dev/video7[17:out]: Queueing buffer 1
[0:02:41.942106423] [1145] DEBUG RPI pisp.cpp:1857 Setting CFE timeout to 1000000.00us
[0:02:41.942149684] [1145] DEBUG RPI pipeline_base.cpp:748 queueRequestDevice: New request sequence: 0
[0:02:41.942169647] [1145] DEBUG RPI pipeline_base.cpp:748 queueRequestDevice: New request sequence: 1
[0:02:41.942185537] [1145] DEBUG RPI pipeline_base.cpp:748 queueRequestDevice: New request sequence: 2
[0:02:41.942202445] [1145] DEBUG RPI pipeline_base.cpp:748 queueRequestDevice: New request sequence: 3
^C

here after the update of rpicam-apps + libcamera (per official Raspberry Pi documentation to compile latest versions) from userspace app started to get looping behaviour, where it errors and then tries to shut it down and start again and loop indefinitely. previously it did this once and froze.

$ libcamera-hello
[5:24:46.860283053] [7021]  INFO Camera camera_manager.cpp:326 libcamera v0.5.1+99-044ceaa4
[5:24:46.872367261] [7022]  INFO RPI pisp.cpp:720 libpisp version v1.2.0 50426319aa1a 11-07-2025 (04:05:47)
[5:24:46.888327895] [7022]  INFO RPI pisp.cpp:1179 Registered camera /base/axi/pcie@1000120000/rp1/i2c@88000/imx290@1a to CFE device /dev/media2 and ISP device /dev/media0 using PiSP variant BCM2712_C0
Preview window unavailable
Mode selection for 960:540:12:P
    SRGGB10_CSI2P,1280x720/0 - Score: 1125
    SRGGB10_CSI2P,1920x1080/0 - Score: 1375
    SRGGB12_CSI2P,1280x720/0 - Score: 125
    SRGGB12_CSI2P,1920x1080/0 - Score: 375
Stream configuration adjusted
[5:24:46.889350085] [7021]  INFO Camera camera.cpp:1205 configuring streams: (0) 960x540-YUV420/sYCC (1) 1280x720-RGGB_PISP_COMP1/RAW
[5:24:46.889462789] [7022]  INFO RPI pisp.cpp:1483 Sensor: /base/axi/pcie@1000120000/rp1/i2c@88000/imx290@1a - Selected sensor format: 1280x720-SRGGB12_1X12 - Selected CFE format: 1280x720-PC1R
[5:24:48.073470252] [7022]  WARN V4L2 v4l2_videodevice.cpp:2151 /dev/video4[16:cap]: Dequeue timer of 1000000.00us has expired!
[5:24:48.073537363] [7022] ERROR RPI pipeline_base.cpp:1346 Camera frontend has timed out!
[5:24:48.073552845] [7022] ERROR RPI pipeline_base.cpp:1347 Please check that your camera sensor connector is attached securely.
[5:24:48.073569178] [7022] ERROR RPI pipeline_base.cpp:1348 Alternatively, try another cable and/or sensor.
ERROR: Device timeout detected, attempting a restart!!!
[5:24:49.261447696] [7022]  WARN V4L2 v4l2_videodevice.cpp:2151 /dev/video4[16:cap]: Dequeue timer of 1000000.00us has expired!
[5:24:49.261489067] [7022] ERROR RPI pipeline_base.cpp:1346 Camera frontend has timed out!
[5:24:49.261504604] [7022] ERROR RPI pipeline_base.cpp:1347 Please check that your camera sensor connector is attached securely.
[5:24:49.261518696] [7022] ERROR RPI pipeline_base.cpp:1348 Alternatively, try another cable and/or sensor.
ERROR: Device timeout detected, attempting a restart!!!
[5:24:50.445452232] [7022]  WARN V4L2 v4l2_videodevice.cpp:2151 /dev/video4[16:cap]: Dequeue timer of 1000000.00us has expired!
[5:24:50.445515084] [7022] ERROR RPI pipeline_base.cpp:1346 Camera frontend has timed out!
[5:24:50.445533214] [7022] ERROR RPI pipeline_base.cpp:1347 Please check that your camera sensor connector is attached securely.
[5:24:50.445560454] [7022] ERROR RPI pipeline_base.cpp:1348 Alternatively, try another cable and/or sensor.
ERROR: Device timeout detected, attempting a restart!!!
[5:24:51.629450840] [7022]  WARN V4L2 v4l2_videodevice.cpp:2151 /dev/video4[16:cap]: Dequeue timer of 1000000.00us has expired!
[5:24:51.629555526] [7022] ERROR RPI pipeline_base.cpp:1346 Camera frontend has timed out!
[5:24:51.629579378] [7022] ERROR RPI pipeline_base.cpp:1347 Please check that your camera sensor connector is attached securely.
[5:24:51.629594211] [7022] ERROR RPI pipeline_base.cpp:1348 Alternatively, try another cable and/or sensor.
ERROR: Device timeout detected, attempting a restart!!!
[5:24:52.813449781] [7022]  WARN V4L2 v4l2_videodevice.cpp:2151 /dev/video4[16:cap]: Dequeue timer of 1000000.00us has expired!
[5:24:52.813477689] [7022] ERROR RPI pipeline_base.cpp:1346 Camera frontend has timed out!
[5:24:52.813485337] [7022] ERROR RPI pipeline_base.cpp:1347 Please check that your camera sensor connector is attached securely.
[5:24:52.813492208] [7022] ERROR RPI pipeline_base.cpp:1348 Alternatively, try another cable and/or sensor.
ERROR: Device timeout detected, attempting a restart!!!
[5:24:53.993448943] [7022]  WARN V4L2 v4l2_videodevice.cpp:2151 /dev/video4[16:cap]: Dequeue timer of 1000000.00us has expired!
[5:24:53.993481480] [7022] ERROR RPI pipeline_base.cpp:1346 Camera frontend has timed out!
[5:24:53.993488869] [7022] ERROR RPI pipeline_base.cpp:1347 Please check that your camera sensor connector is attached securely.
[5:24:53.993495647] [7022] ERROR RPI pipeline_base.cpp:1348 Alternatively, try another cable and/or sensor.
ERROR: Device timeout detected, attempting a restart!!!
[5:24:55.177451569] [7022]  WARN V4L2 v4l2_videodevice.cpp:2151 /dev/video4[16:cap]: Dequeue timer of 1000000.00us has expired!
[5:24:55.177480476] [7022] ERROR RPI pipeline_base.cpp:1346 Camera frontend has timed out!
[5:24:55.177487773] [7022] ERROR RPI pipeline_base.cpp:1347 Please check that your camera sensor connector is attached securely.
[5:24:55.177494365] [7022] ERROR RPI pipeline_base.cpp:1348 Alternatively, try another cable and/or sensor.
ERROR: Device timeout detected, attempting a restart!!!
^C

$ dmesg
[    0.000000] Booting Linux on physical CPU 0x0000000000 [0x414fd0b1]
[    0.000000] Linux version 6.12.36-v8-16k+ (dom@buildbot) (aarch64-linux-gnu-gcc (Ubuntu 11.4.0-1ubuntu1~22.04) 11.4.0, GNU ld (GNU Binutils for Ubuntu) 2.38) #1892 SMP PREEMPT Mon Jul  7 17:14:15 BST 2025
[    0.000000] KASLR enabled
[    0.000000] random: crng init done
[    0.000000] Machine model: Raspberry Pi 5 Model B Rev 1.0
[    0.000000] printk: debug: ignoring loglevel setting.
[    9.859986] vc4_hvs 107c580000.hvs: Adding to iommu group 1
[    9.860036] Bluetooth: hci0: BCM: chip id 107
[    9.862327] rp1-cfe 1f00110000.csi: Registered [rp1-cfe-csi2_ch2] node id 2 successfully as /dev/video2
[    9.862391] rp1-cfe 1f00110000.csi: Registered [rp1-cfe-csi2_ch3] node id 3 successfully as /dev/video3
[    9.862904] rp1-cfe 1f00110000.csi: Registered [rp1-cfe-fe_image0] node id 4 successfully as /dev/video4
[    9.863326] rp1-cfe 1f00110000.csi: Registered [rp1-cfe-fe_image1] node id 5 successfully as /dev/video5
[    9.863397] rp1-cfe 1f00110000.csi: Registered [rp1-cfe-fe_stats] node id 6 successfully as /dev/video6
[    9.863453] rp1-cfe 1f00110000.csi: Registered [rp1-cfe-fe_config] node id 7 successfully as /dev/video7
..
[  161.254757] rp1-cfe 1f00110000.csi: Using a link rate of 594 Mbps
[16437.576940] ------------[ cut here ]------------
[16437.581841] WARNING: CPU: 2 PID: 1152 at drivers/media/v4l2-core/v4l2-subdev.c:457 call_s_stream+0xe8/0x110 [videodev]
[16437.592874] Modules linked in: rfcomm snd_seq_dummy snd_hrtimer snd_seq snd_seq_device algif_hash algif_skcipher af_alg bnep binfmt_misc brcmfmac_wcc vc4 brcmfmac imx290 snd_soc_hdmi_codec drm_display_helper brcmutil cec v4l2_cci regmap_i2c spidev drm_dma_helper snd_soc_core hci_uart aes_ce_blk btbcm cfg80211 aes_ce_cipher ghash_ce bluetooth snd_compress snd_pcm_dmaengine rp1_cfe gf128mul rpi_hevc_dec pisp_be sha2_ce snd_pcm ecdh_generic sha256_arm64 ecc sha1_ce rfkill v4l2_fwnode libaes v4l2_mem2mem snd_timer videobuf2_dma_contig v4l2_async snd videobuf2_memops sha1_generic videobuf2_v4l2 videodev raspberrypi_hwmon v3d videobuf2_common gpio_keys spi_bcm2835 mc i2c_brcmstb gpu_sched pwm_fan rp1_pio drm_shmem_helper rp1_mailbox i2c_designware_platform rp1_adc drm_kms_helper rp1_fw raspberrypi_gpiomem i2c_designware_core nvmem_rmem uio_pdrv_genirq uio i2c_dev drm drm_panel_orientation_quirks backlight dm_mod fuse ip_tables x_tables ipv6
[16437.676414] CPU: 2 UID: 1000 PID: 1152 Comm: libcamera-hello Not tainted 6.12.36-v8-16k+ #1892
[16437.685321] Hardware name: Raspberry Pi 5 Model B Rev 1.0 (DT)
[16437.691433] pstate: 60400009 (nZCv daif +PAN -UAO -TCO -DIT -SSBS BTYPE=--)
[16437.698681] pc : call_s_stream+0xe8/0x110 [videodev]
[16437.703934] lr : cfe_stop_streaming+0xdc/0x210 [rp1_cfe]
[16437.709525] sp : ffffc00084553a00
[16437.713106] x29: ffffc00084553a00 x28: ffff8000a0fe0000 x27: 0000000000000000
[16437.720530] x26: 0000000000000009 x25: 0000000000000001 x24: ffff8000a0fe0600
[16437.727953] x23: ffff8000e0f10370 x22: 0000000000000000 x21: ffff8000e0f13b68
[16437.735376] x20: ffff8000e0f10000 x19: 0000000000000008 x18: ffffc00084553ae0
[16437.742799] x17: 0000000000000000 x16: ffffd06fcf1a9f68 x15: ffffd06fcf2fe548
[16437.750222] x14: ffff80001ffaa730 x13: ffffffffffffffff x12: ffffd06fcf2fe548
[16437.757645] x11: 0000000000000001 x10: 0000000000000002 x9 : ffffd06f68b93164
[16437.765067] x8 : 0000000000000000 x7 : 00000000000000e0 x6 : 0000000000000025
[16437.772491] x5 : ffff8000e0f14358 x4 : 0000000000000000 x3 : ffffd06f68899c18
[16437.779913] x2 : 0000000000000000 x1 : 0000000000000000 x0 : ffff8000e0c174a8
[16437.787336] Call trace:
[16437.790045]  call_s_stream+0xe8/0x110 [videodev]
[16437.794948]  cfe_stop_streaming+0xdc/0x210 [rp1_cfe]
[16437.800188]  __vb2_queue_cancel+0x34/0x2d8 [videobuf2_common]
[16437.806220]  vb2_core_queue_release+0x2c/0x88 [videobuf2_common]
[16437.812510]  _vb2_fop_release+0x7c/0x90 [videobuf2_v4l2]
[16437.818102]  vb2_fop_release+0x34/0x68 [videobuf2_v4l2]
[16437.823605]  v4l2_release+0xec/0x100 [videodev]
[16437.828421]  __fput+0xd0/0x2e0
[16437.831743]  ____fput+0x1c/0x30
[16437.835150]  task_work_run+0x78/0xe0
[16437.838995]  do_exit+0x2e8/0x9c0
[16437.842492]  do_group_exit+0x3c/0xa0
[16437.846336]  get_signal+0x9e0/0x9e8
[16437.850094]  do_signal+0x94/0x10d0
[16437.853763]  do_notify_resume+0xd0/0x150
[16437.857958]  el0_svc+0xd8/0x100
[16437.861366]  el0t_64_sync_handler+0x13c/0x158
[16437.865995]  el0t_64_sync+0x190/0x198
[16437.869927] ---[ end trace 0000000000000000 ]---
[19487.345160] rp1-cfe 1f00110000.csi: Using a link rate of 594 Mbps
[19488.561441] rp1-cfe 1f00110000.csi: Using a link rate of 594 Mbps
[19489.745152] rp1-cfe 1f00110000.csi: Using a link rate of 594 Mbps
[19490.929203] rp1-cfe 1f00110000.csi: Using a link rate of 594 Mbps
[19492.117125] rp1-cfe 1f00110000.csi: Using a link rate of 594 Mbps
[19493.297106] rp1-cfe 1f00110000.csi: Using a link rate of 594 Mbps
[19494.477119] rp1-cfe 1f00110000.csi: Using a link rate of 594 Mbps
[19495.661109] rp1-cfe 1f00110000.csi: Using a link rate of 594 Mbps

Additional context

No response

xrdelectro avatar Jul 31 '25 19:07 xrdelectro

Technically this isn't a kernel crash, it's a WARN (i.e. a "something unexpected happened" that is handled). The code is:

	/*
	 * The .s_stream() operation must never be called to start or stop an
	 * already started or stopped subdev. Catch offenders but don't return
	 * an error yet to avoid regressions.
	 */
	if (WARN_ON(sd->s_stream_enabled == !!enable))
		return 0;

But that's the limit of my knowledge on this subject.

popcornmix avatar Aug 01 '25 09:08 popcornmix

It's a catch for CSI2 receiver drivers that have called s_stream(true) to start streaming when already streaming, or s_stream(false) to stop streaming when already stopped. You've obviously found a path in the CFE driver that can achieve that.

Without some more guidance on how to reproduce this, there is limited chance to find that path. It would appear to be in the error recovery path, but a number of things can trigger that.

I'm also conscious that this is on our downstream version of the CFE driver. The CFE driver has been upstreamed to mainline Linux now, but currently has a few limitations so we haven't adopted it. Tracking down issues in the downstream driver that will hopefully get thrown away within a year is of limited gain.

6by9 avatar Aug 04 '25 13:08 6by9

Amusingly I've just hit the same WARNING. It appears to be that the "no frame received" timeout in libcamera manages to trigger it fairly reliably with imx219.

It doesn't appear to affect ov5647, so I was expecting that it was only sensors using embedded metadata that triggered it, but that wouldn't apply to the imx290 (at least the version in mainline and our kernel). And now double checking I see that the imx219 kernel driver has dropped embedded metadata in 6.12. Count me confused!

6by9 avatar Aug 07 '25 18:08 6by9