Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Network booted RPI 3B+ modprobe bcm2835-v4l2 freezes machine #2528

Closed
jonshouse1 opened this issue Apr 23, 2018 · 40 comments
Closed

Network booted RPI 3B+ modprobe bcm2835-v4l2 freezes machine #2528

jonshouse1 opened this issue Apr 23, 2018 · 40 comments

Comments

@jonshouse1
Copy link

NFS root RPI3B+

I have a working card image, works with my v4l app, camera works fine.

I made a network booting image of the same files, boots ok its just now it hard locks loading the module. Modprobe of other modules is ok.

Linux raspberrypi 4.9.80-v7+ #1098 SMP Fri Mar 9 19:11:42 GMT 2018 armv7l GNU/Linux

I can switch between booting form the sd card or the LAN, sdcard always works, LAN boot always locks if I try and load the module.
Even tried copying the modules to a tempfs mount point and using "modprobe -d", still locks up.

@jonshouse1
Copy link
Author

jonshouse1 commented Apr 23, 2018

Just tried upgrading

root@raspberrypi:~# uname -a
Linux raspberrypi 4.14.34-v7+ #1110 SMP Mon Apr 16 15:18:51 BST 2018 armv7l GNU/Linux
root@raspberrypi:~# modprobe bcm2835-v4l2

Still freezes machine, Keyboard unresponsive, does not ping etc etc...

@jonshouse1
Copy link
Author

Did an rpi-update, still same, tried a couple of different PSU for good luck as well

root@raspberrypi:/boot# /opt/vc/bin/vcgencmd version
Apr 16 2018 18:21:52 
Copyright (c) 2012 Broadcom
version af8084725947aa2c7314172068f79dad9be1c8b4 (clean) (release)
root@raspberrypi:/boot# uname -a
Linux raspberrypi 4.14.34-v7+ #1110 SMP Mon Apr 16 15:18:51 BST 2018 armv7l GNU/Linux

@6by9
Copy link
Contributor

6by9 commented Apr 24, 2018

This looks like a duplicate of #2335 (ignore the title).

@pelwell
Copy link
Contributor

pelwell commented Apr 24, 2018

Testing with a 3B+ booting from SD card but with an NFS root partition I see no problems - it just works.

Are you booting:
a) with no SD card, TFTP for bootcode.bin and start.elf, NFS root,
b) bootcode.bin on SD card, then TFTP boot for start.elf and NFS root, or
c) firmware and kernel on SD card, root on NFS drive?

@pelwell
Copy link
Contributor

pelwell commented Apr 24, 2018

Now tested with a fully network-booted 3B+ - again, no problems.

@6by9
Copy link
Contributor

6by9 commented Apr 24, 2018

With #2335 I did have it failing on a 2 or 3B with only bootcode.bin on the SD card and talking to PiServer.
I couldn't determine a reason for it stalling NFS, but not having called bcm_host_init resulted in the VCHI calls during bcm2835-v4l2 probe to have nasty side-effects. I'll see if I can fire up my PiServer install again and reproduce.

@6by9
Copy link
Contributor

6by9 commented Apr 24, 2018

Updated my PiServer from 4.9.xx to 4.14.34 (latest from apt).
Reproducable on a 3B IFF you have the camera plugged in. Without the camera it checks the number of cameras detected (0) and aborts. Most odd as both bits use the same MMAL framework.

@jonshouse1
Copy link
Author

Are you booting:
a) with no SD card, TFTP for bootcode.bin and start.elf, NFS root,

No SD card.

I have firmware in a directory with the name of the Pi serial number "25bcbfa6"

root@mail:/disks/vol1/tftpboot/25bcbfa6# md5sum * e3ab88859237eeb7f8deb8ef9f9af2bd bcm2708-rpi-0-w.dtb 3501aebf7f08798dfa44f38422b30550 bcm2708-rpi-b.dtb 8154d0a768147413019fa98c18ac9398 bcm2708-rpi-b-plus.dtb b07a7eccd032e98e5ee866c02f415f84 bcm2708-rpi-cm.dtb 4c73875b9db6a1e55824e3b3f005406f bcm2709-rpi-2-b.dtb a81f9a6a9bbc7b83209512021c9c248b bcm2710-rpi-3-b.dtb c2e9f69eff3551644a600721eed4ea07 bcm2710-rpi-3-b-plus.dtb 5d0680a605e98ba5ff7e3716ecab27d0 bcm2710-rpi-cm3.dtb 17efaf1c1ef89289168d71cdc8194982 bootcode.bin 935439b96482e274890752e0a4c16946 cmdline.OLD 0875c9770bb841b69915a74a82e4eb3d cmdline.txt e3f0a57ceef109eb13d94df7f8b95132 config.txt d7810fab7487fb0aad327b76f1be7cd7 COPYING.linux 253315e7f9ca4b64dbe69a62f2456c50 fixup_cd.dat da5a8b0ad03be4dc6deaad85eca8e52d fixup.dat 59775794d283ab35d83532fc8fdefe46 fixup_db.dat c1b836cccef2a337f8e236154c5d15eb fixup_x.dat bdc6492254aec36a53f90506a22ba6a9 issue.txt 2926f6994558d63e70d6f3999a082a90 kernel7.img d092c0f9628577f8970adbf7eecc49c1 kernel.img 4a4d169737c0786fb9482bb6d30401d1 LICENCE.broadcom bcd91fdfffb0cf7518016189fca363ee LICENSE.oracle md5sum: overlays: Is a directory e203c4d048030f412acbf7034dc4886a start_cd.elf c8c3486368d8be92ffe1673eccc68911 start_db.elf 8a8e2c3cf9b6ce177e50f748eb91e816 start.elf 9fc019c14638acd381f9027317cc855a start_x.elf
Root file system is then via NFS.

Board is a Pi 3B+, yes with the camera attached. The idea is to have NFS booted cameras, I have purchases 10 camera modules so it would be great if this could be sorted. I assure the issue is real and can provide unexciting video if needs be.
Thanks, Jon.

@6by9
Copy link
Contributor

6by9 commented Apr 24, 2018

pelwell's just confirmed that he had no camera attached, so that sort of confirms my earlier debug.

I have seen a little mismatch in resource allocation/free, but don't see how that would cause these issues. It's odd as there isn't anything fundamentally different between SD card and network booting.
I've currently broken my kernel build of the V4L2 driver totally so that it won't load, therefore need to fix that first :-(

@pelwell
Copy link
Contributor

pelwell commented Apr 24, 2018

I can also confirm that it wedges with a camera attached.

With some VCHIQ logging enabled at the same I see the following kernel logging:

[  123.209851] media: Linux media interface: v0.10
[  123.245878] Linux video capture interface: v2.00
[  123.279314] bcm2835_v4l2: module is from the staging directory, the quality is unknown, you have been warned.
[  123.280499] vchiq: Open Service mmal SrcPort:2
[  123.280526] vchiq: Sent Msg OPEN(2) to ???? s:2 d:0 len:12
[  123.280588] vchiq: Rcvd Msg OPENACK(3) from mmal s:86 d:2 len:2
[  123.280597] vchiq: Rcvd: 00000000: 10 00                                           ..
[  123.280647] vchiq: Sent: 00000000: 6d 6d 61 6c 04 00 00 00 00 00 00 00 01 00 00 00 mmal............
[  123.280654] vchiq: Sent Msg DATA(5) to mmal s:2 d:86 len:160
[  123.281024] vchiq: Rcvd Msg DATA(5) from mmal s:86 d:2 len:44
[  123.281039] vchiq: Rcvd: 00000000: 6d 6d 61 6c 04 00 00 00 44 ce 3d 3f 01 00 00 00 mmal....D.=?....
[  123.281098] vchiq: Sent: 00000000: 6d 6d 61 6c 08 00 00 00 6d 6d 61 6c 02 00 00 00 mmal....mmal....
[  123.281103] vchiq: Sent Msg DATA(5) to mmal s:2 d:86 len:36
[  123.281155] vchiq: Rcvd Msg DATA(5) from mmal s:86 d:2 len:316
[  123.281168] vchiq: Rcvd: 00000000: 6d 6d 61 6c 08 00 00 00 44 ce 3d 3f 02 00 00 00 mmal....D.=?....
[  123.281361] vchiq: Sent: 00000000: 6d 6d 61 6c 0f 00 00 00 00 00 00 00 03 00 00 00 mmal............
[  123.281365] vchiq: Sent Msg DATA(5) to mmal s:2 d:86 len:40
[  123.281432] vchiq: Rcvd Msg DATA(5) from mmal s:86 d:2 len:180
[  123.281447] vchiq: Rcvd: 00000000: 6d 6d 61 6c 0f 00 00 00 44 ce 3d 3f 03 00 00 00 mmal....D.=?....
[  123.281484] vchiq: Sent: 00000000: 6d 6d 61 6c 05 00 00 00 00 00 00 00 04 00 00 00 mmal............
[  123.281488] vchiq: Sent Msg DATA(5) to mmal s:2 d:86 len:28
[  123.281606] vchiq: Rcvd Msg DATA(5) from mmal s:86 d:2 len:28
[  123.281628] vchiq: Rcvd: 00000000: 6d 6d 61 6c 05 00 00 00 44 ce 3d 3f 04 00 00 00 mmal....D.=?....
[  123.281809] vchiq: Open Service mmal SrcPort:3
[  123.281818] vchiq: Sent Msg OPEN(2) to ???? s:3 d:0 len:12
[  123.281866] vchiq: Rcvd Msg OPENACK(3) from mmal s:88 d:3 len:2
[  123.281873] vchiq: Rcvd: 00000000: 10 00                                           ..
[  123.281913] vchiq: Sent: 00000000: 6d 6d 61 6c 04 00 00 00 00 00 00 00 01 00 00 00 mmal............
[  123.281917] vchiq: Sent Msg DATA(5) to mmal s:3 d:88 len:160
[  123.283885] WARN::dwc_otg_hcd_handle_hc_fsm:2458: Unexpected IRQ state on FSM transaction:dev_addr=4 ep=2 fsm=6, hcint=0x00000002
[  123.315864] WARN::dwc_otg_hcd_handle_hc_fsm:2458: Unexpected IRQ state on FSM transaction:dev_addr=4 ep=2 fsm=6, hcint=0x00000002
[  123.331860] WARN::dwc_otg_hcd_handle_hc_fsm:2458: Unexpected IRQ state on FSM transaction:dev_addr=4 ep=1 fsm=6, hcint=0x00000002
[  125.450280] vchiq: Rcvd Msg DATA(5) from mmal s:88 d:3 len:44
[  125.450337] vchiq: Rcvd: 00000000: 6d 6d 61 6c 04 00 00 00 f4 82 3d 3f 01 00 00 00 mmal......=?....
[  125.450431] vchiq: Sent: 00000000: 6d 6d 61 6c 08 00 00 00 6d 6d 61 6c 02 00 00 00 mmal....mmal....
[  125.450442] vchiq: Sent Msg DATA(5) to mmal s:3 d:88 len:36
[  125.450510] vchiq: Rcvd Msg DATA(5) from mmal s:88 d:3 len:316
[  125.450533] vchiq: Rcvd: 00000000: 6d 6d 61 6c 08 00 00 00 f4 82 3d 3f 02 00 00 00 mmal......=?....
[  125.450590] vchiq: Sent: 00000000: 6d 6d 61 6c 08 00 00 00 6d 6d 61 6c 03 00 00 00 mmal....mmal....
[  125.450600] vchiq: Sent Msg DATA(5) to mmal s:3 d:88 len:36
[  125.450656] vchiq: Rcvd Msg DATA(5) from mmal s:88 d:3 len:316
[  125.450680] vchiq: Rcvd: 00000000: 6d 6d 61 6c 08 00 00 00 f4 82 3d 3f 03 00 00 00 mmal......=?....
[  125.450735] vchiq: Sent: 00000000: 6d 6d 61 6c 08 00 00 00 6d 6d 61 6c 04 00 00 00 mmal....mmal....
[  125.450744] vchiq: Sent Msg DATA(5) to mmal s:3 d:88 len:36
[  125.450815] vchiq: Rcvd Msg DATA(5) from mmal s:88 d:3 len:316
[  125.450838] vchiq: Rcvd: 00000000: 6d 6d 61 6c 08 00 00 00 f4 82 3d 3f 04 00 00 00 mmal......=?....
[  125.450896] vchiq: Sent: 00000000: 6d 6d 61 6c 08 00 00 00 6d 6d 61 6c 05 00 00 00 mmal....mmal....
[  125.450905] vchiq: Sent Msg DATA(5) to mmal s:3 d:88 len:36
[  125.450961] vchiq: Rcvd Msg DATA(5) from mmal s:88 d:3 len:316
[  125.450986] vchiq: Rcvd: 00000000: 6d 6d 61 6c 08 00 00 00 f4 82 3d 3f 05 00 00 00 mmal......=?....
[  125.451041] vchiq: Sent: 00000000: 6d 6d 61 6c 08 00 00 00 6d 6d 61 6c 06 00 00 00 mmal....mmal....
[  125.451050] vchiq: Sent Msg DATA(5) to mmal s:3 d:88 len:36
[  125.451106] vchiq: Rcvd Msg DATA(5) from mmal s:88 d:3 len:316
[  125.451129] vchiq: Rcvd: 00000000: 6d 6d 61 6c 08 00 00 00 f4 82 3d 3f 06 00 00 00 mmal......=?....
[  125.451187] vchiq: Sent: 00000000: 6d 6d 61 6c 0e 00 00 00 54 7a 52 b7 07 00 00 00 mmal....TzR.....
[  125.451196] vchiq: Sent Msg DATA(5) to mmal s:3 d:88 len:80
[  125.451305] vchiq: Rcvd Msg DATA(5) from mmal s:88 d:3 len:28
[  125.451328] vchiq: Rcvd: 00000000: 6d 6d 61 6c 0e 00 00 00 f4 82 3d 3f 07 00 00 00 mmal......=?....
[  125.451379] vchiq: Sent: 00000000: 6d 6d 61 6c 0f 00 00 00 00 00 00 00 08 00 00 00 mmal............
[  125.451388] vchiq: Sent Msg DATA(5) to mmal s:3 d:88 len:40
[  125.451500] vchiq: Rcvd Msg DATA(5) from mmal s:88 d:3 len:92
[  125.451523] vchiq: Rcvd: 00000000: 6d 6d 61 6c 0f 00 00 00 f4 82 3d 3f 08 00 00 00 mmal......=?....
[  125.451575] vchiq: Sent: 00000000: 6d 6d 61 6c 0e 00 00 00 00 00 00 00 09 00 00 00 mmal............
[  125.451584] vchiq: Sent Msg DATA(5) to mmal s:3 d:88 len:44
[  125.451669] vchiq: Rcvd Msg DATA(5) from mmal s:88 d:3 len:28
[  125.451692] vchiq: Rcvd: 00000000: 6d 6d 61 6c 0e 00 00 00 f4 82 3d 3f 09 00 00 00 mmal......=?....
[  125.451742] vchiq: Sent: 00000000: 6d 6d 61 6c 0e 00 00 00 00 00 00 00 0a 00 00 00 mmal............
[  125.451751] vchiq: Sent Msg DATA(5) to mmal s:3 d:88 len:44
[  125.451826] vchiq: Rcvd Msg DATA(5) from mmal s:88 d:3 len:28
[  125.451848] vchiq: Rcvd: 00000000: 6d 6d 61 6c 0e 00 00 00 f4 82 3d 3f 0a 00 00 00 mmal......=?....
[  125.451903] vchiq: Sent: 00000000: 6d 6d 61 6c 04 00 00 00 6d 6d 61 6c 0b 00 00 00 mmal....mmal....
[  125.451913] vchiq: Sent Msg DATA(5) to mmal s:3 d:88 len:160
[  125.452617] vchiq: Rcvd Msg DATA(5) from mmal s:88 d:3 len:44
[  125.452640] vchiq: Rcvd: 00000000: 6d 6d 61 6c 04 00 00 00 f4 82 3d 3f 0b 00 00 00 mmal......=?....
[  125.452690] vchiq: Sent: 00000000: 6d 6d 61 6c 08 00 00 00 6d 6d 61 6c 0c 00 00 00 mmal....mmal....
[  125.452699] vchiq: Sent Msg DATA(5) to mmal s:3 d:88 len:36
[  125.452757] vchiq: Rcvd Msg DATA(5) from mmal s:88 d:3 len:316
[  125.452780] vchiq: Rcvd: 00000000: 6d 6d 61 6c 08 00 00 00 f4 82 3d 3f 0c 00 00 00 mmal......=?....
[  125.452836] vchiq: Sent: 00000000: 6d 6d 61 6c 08 00 00 00 6d 6d 61 6c 0d 00 00 00 mmal....mmal....
[  125.452846] vchiq: Sent Msg DATA(5) to mmal s:3 d:88 len:36
[  125.452901] vchiq: Rcvd Msg DATA(5) from mmal s:88 d:3 len:316
[  125.452926] vchiq: Rcvd: 00000000: 6d 6d 61 6c 08 00 00 00 f4 82 3d 3f 0d 00 00 00 mmal......=?....
[  125.452985] vchiq: Sent: 00000000: 6d 6d 61 6c 04 00 00 00 00 00 00 00 0e 00 00 00 mmal............
[  125.452994] vchiq: Sent Msg DATA(5) to mmal s:3 d:88 len:160
[  125.454062] vchiq: Rcvd Msg DATA(5) from mmal s:88 d:3 len:44
[  125.454085] vchiq: Rcvd: 00000000: 6d 6d 61 6c 04 00 00 00 f4 82 3d 3f 0e 00 00 00 mmal......=?....
[  125.454137] vchiq: Sent: 00000000: 6d 6d 61 6c 08 00 00 00 6d 6d 61 6c 0f 00 00 00 mmal....mmal....
[  125.454146] vchiq: Sent Msg DATA(5) to mmal s:3 d:88 len:36
[  125.454217] vchiq: Rcvd Msg DATA(5) from mmal s:88 d:3 len:316
[  125.454240] vchiq: Rcvd: 00000000: 6d 6d 61 6c 08 00 00 00 f4 82 3d 3f 0f 00 00 00 mmal......=?....
[  125.454292] vchiq: Sent: 00000000: 6d 6d 61 6c 08 00 00 00 6d 6d 61 6c 10 00 00 00 mmal....mmal....
[  125.454301] vchiq: Sent Msg DATA(5) to mmal s:3 d:88 len:36
[  125.454355] vchiq: Rcvd Msg DATA(5) from mmal s:88 d:3 len:316
[  125.454379] vchiq: Rcvd: 00000000: 6d 6d 61 6c 08 00 00 00 f4 82 3d 3f 10 00 00 00 mmal......=?....
[  125.454433] vchiq: Sent: 00000000: 6d 6d 61 6c 08 00 00 00 6d 6d 61 6c 11 00 00 00 mmal....mmal....
[  125.454442] vchiq: Sent Msg DATA(5) to mmal s:3 d:88 len:36
[  125.454499] vchiq: Rcvd Msg PADDING(0) from ???? s:0 d:0 len:8
[  125.454515] vchiq: Rcvd: 00000000: 00 00 00 00 00 00 00 00                         ........
[  125.454528] vchiq: Rcvd Msg DATA(5) from mmal s:88 d:3 len:316
[  125.454551] vchiq: Rcvd: 00000000: 6d 6d 61 6c 08 00 00 00 f4 82 3d 3f 11 00 00 00 mmal......=?....
[  125.454606] vchiq: Sent: 00000000: 6d 6d 61 6c 04 00 00 00 00 00 00 00 12 00 00 00 mmal............
[  125.454615] vchiq: Sent Msg DATA(5) to mmal s:3 d:88 len:160
[  125.455665] vchiq: Rcvd Msg DATA(5) from mmal s:88 d:3 len:44
[  125.455688] vchiq: Rcvd: 00000000: 6d 6d 61 6c 04 00 00 00 f4 82 3d 3f 12 00 00 00 mmal......=?....
[  125.455741] vchiq: Sent: 00000000: 6d 6d 61 6c 08 00 00 00 6d 6d 61 6c 13 00 00 00 mmal....mmal....
[  125.455751] vchiq: Sent Msg DATA(5) to mmal s:3 d:88 len:36
[  125.455812] vchiq: Rcvd Msg DATA(5) from mmal s:88 d:3 len:316
[  125.455834] vchiq: Rcvd: 00000000: 6d 6d 61 6c 08 00 00 00 f4 82 3d 3f 13 00 00 00 mmal......=?....
[  125.455890] vchiq: Sent: 00000000: 6d 6d 61 6c 08 00 00 00 6d 6d 61 6c 14 00 00 00 mmal....mmal....
[  125.455899] vchiq: Sent Msg DATA(5) to mmal s:3 d:88 len:36
[  125.455953] vchiq: Rcvd Msg DATA(5) from mmal s:88 d:3 len:316
[  125.455978] vchiq: Rcvd: 00000000: 6d 6d 61 6c 08 00 00 00 f4 82 3d 3f 14 00 00 00 mmal......=?....
[  125.456033] vchiq: Sent: 00000000: 6d 6d 61 6c 08 00 00 00 6d 6d 61 6c 15 00 00 00 mmal....mmal....
[  125.456041] vchiq: Sent Msg DATA(5) to mmal s:3 d:88 len:36
[  125.456098] vchiq: Rcvd Msg DATA(5) from mmal s:88 d:3 len:316
[  125.456121] vchiq: Rcvd: 00000000: 6d 6d 61 6c 08 00 00 00 f4 82 3d 3f 15 00 00 00 mmal......=?....
[  125.456176] vchiq: Sent: 00000000: 6d 6d 61 6c 09 00 00 00 28 00 00 00 16 00 00 00 mmal....(.......
[  125.456185] vchiq: Sent Msg DATA(5) to mmal s:3 d:88 len:304
[  125.456301] vchiq: Rcvd Msg DATA(5) from mmal s:88 d:3 len:316
[  125.456324] vchiq: Rcvd: 00000000: 6d 6d 61 6c 09 00 00 00 f4 82 3d 3f 16 00 00 00 mmal......=?....
[  125.456373] vchiq: Sent: 00000000: 6d 6d 61 6c 08 00 00 00 00 00 00 00 17 00 00 00 mmal............
[  125.456382] vchiq: Sent Msg DATA(5) to mmal s:3 d:88 len:36
[  125.456439] vchiq: Rcvd Msg DATA(5) from mmal s:88 d:3 len:316
[  125.456462] vchiq: Rcvd: 00000000: 6d 6d 61 6c 08 00 00 00 f4 82 3d 3f 17 00 00 00 mmal......=?....
[  125.456515] vchiq: Sent: 00000000: 6d 6d 61 6c 0e 00 00 00 6d 6d 61 6c 18 00 00 00 mmal....mmal....
[  125.456524] vchiq: Sent Msg DATA(5) to mmal s:3 d:88 len:44
[  125.456622] vchiq: Rcvd Msg DATA(5) from mmal s:88 d:3 len:28
[  125.456645] vchiq: Rcvd: 00000000: 6d 6d 61 6c 0e 00 00 00 f4 82 3d 3f 18 00 00 00 mmal......=?....
[  125.456693] vchiq: Sent: 00000000: 6d 6d 61 6c 0e 00 00 00 6d 6d 61 6c 19 00 00 00 mmal....mmal....
[  125.456702] vchiq: Sent Msg DATA(5) to mmal s:3 d:88 len:44
[  125.456782] vchiq: Rcvd Msg DATA(5) from mmal s:88 d:3 len:28
[  125.456806] vchiq: Rcvd: 00000000: 6d 6d 61 6c 0e 00 00 00 f4 82 3d 3f 19 00 00 00 mmal......=?....
[  125.456856] vchiq: Sent: 00000000: 6d 6d 61 6c 0e 00 00 00 80 94 65 80 1a 00 00 00 mmal......e.....
[  125.456865] vchiq: Sent Msg DATA(5) to mmal s:3 d:88 len:48
[  125.456975] vchiq: Rcvd Msg DATA(5) from mmal s:88 d:3 len:28
[  125.457000] vchiq: Rcvd: 00000000: 6d 6d 61 6c 0e 00 00 00 f4 82 3d 3f 1a 00 00 00 mmal......=?....
[  125.457051] vchiq: Sent: 00000000: 6d 6d 61 6c 0e 00 00 00 80 94 65 80 1b 00 00 00 mmal......e.....
[  125.457060] vchiq: Sent Msg DATA(5) to mmal s:3 d:88 len:48
[  125.457137] vchiq: Rcvd Msg DATA(5) from mmal s:88 d:3 len:28
[  125.457162] vchiq: Rcvd: 00000000: 6d 6d 61 6c 0e 00 00 00 f4 82 3d 3f 1b 00 00 00 mmal......=?....
[  125.457211] vchiq: Sent: 00000000: 6d 6d 61 6c 0e 00 00 00 80 94 65 80 1c 00 00 00 mmal......e.....
[  125.457220] vchiq: Sent Msg DATA(5) to mmal s:3 d:88 len:48
[  125.457300] vchiq: Rcvd Msg DATA(5) from mmal s:88 d:3 len:28
[  125.457322] vchiq: Rcvd: 00000000: 6d 6d 61 6c 0e 00 00 00 f4 82 3d 3f 1c 00 00 00 mmal......=?....
[  125.457372] vchiq: Sent: 00000000: 6d 6d 61 6c 0e 00 00 00 80 94 65 80 1d 00 00 00 mmal......e.....
[  125.457381] vchiq: Sent Msg DATA(5) to mmal s:3 d:88 len:48
[  125.457456] vchiq: Rcvd Msg DATA(5) from mmal s:88 d:3 len:28
[  125.457479] vchiq: Rcvd: 00000000: 6d 6d 61 6c 0e 00 00 00 f4 82 3d 3f 1d 00 00 00 mmal......=?....
[  125.457530] vchiq: Sent: 00000000: 6d 6d 61 6c 0e 00 00 00 00 00 00 00 1e 00 00 00 mmal............
[  125.457539] vchiq: Sent Msg DATA(5) to mmal s:3 d:88 len:44
[  125.457624] vchiq: Rcvd Msg DATA(5) from mmal s:88 d:3 len:28
[  125.457647] vchiq: Rcvd: 00000000: 6d 6d 61 6c 0e 00 00 00 f4 82 3d 3f 1e 00 00 00 mmal......=?....
[  125.457697] vchiq: Sent: 00000000: 6d 6d 61 6c 0e 00 00 00 00 00 00 00 1f 00 00 00 mmal............
[  125.457706] vchiq: Sent Msg DATA(5) to mmal s:3 d:88 len:44
[  125.457785] vchiq: Rcvd Msg DATA(5) from mmal s:88 d:3 len:28
[  125.457809] vchiq: Rcvd: 00000000: 6d 6d 61 6c 0e 00 00 00 f4 82 3d 3f 1f 00 00 00 mmal......=?....
[  125.457860] vchiq: Sent: 00000000: 6d 6d 61 6c 0e 00 00 00 6d 6d 61 6c 20 00 00 00 mmal....mmal ...
[  125.457869] vchiq: Sent Msg DATA(5) to mmal s:3 d:88 len:44
[  125.457943] vchiq: Rcvd Msg DATA(5) from mmal s:88 d:3 len:28
[  125.457966] vchiq: Rcvd: 00000000: 6d 6d 61 6c 0e 00 00 00 f4 82 3d 3f 20 00 00 00 mmal......=? ...
[  125.458019] vchiq: Sent: 00000000: 6d 6d 61 6c 0e 00 00 00 6d 6d 61 6c 21 00 00 00 mmal....mmal!...
[  125.458028] vchiq: Sent Msg DATA(5) to mmal s:3 d:88 len:44
[  125.458108] vchiq: Rcvd Msg DATA(5) from mmal s:88 d:3 len:28
[  125.458131] vchiq: Rcvd: 00000000: 6d 6d 61 6c 0e 00 00 00 f4 82 3d 3f 21 00 00 00 mmal......=?!...
[  125.458181] vchiq: Sent: 00000000: 6d 6d 61 6c 0e 00 00 00 6d 6d 61 6c 22 00 00 00 mmal....mmal"...
[  125.458190] vchiq: Sent Msg DATA(5) to mmal s:3 d:88 len:44
[  125.458269] vchiq: Rcvd Msg DATA(5) from mmal s:88 d:3 len:28
[  125.458292] vchiq: Rcvd: 00000000: 6d 6d 61 6c 0e 00 00 00 f4 82 3d 3f 22 00 00 00 mmal......=?"...
[  125.458343] vchiq: Sent: 00000000: 6d 6d 61 6c 0e 00 00 00 a0 5b 66 80 23 00 00 00 mmal.....[f.#...
[  125.458352] vchiq: Sent Msg DATA(5) to mmal s:3 d:88 len:56
[  125.458432] vchiq: Rcvd Msg DATA(5) from mmal s:88 d:3 len:28
[  125.458455] vchiq: Rcvd: 00000000: 6d 6d 61 6c 0e 00 00 00 f4 82 3d 3f 23 00 00 00 mmal......=?#...
[  125.458506] vchiq: Sent: 00000000: 6d 6d 61 6c 0e 00 00 00 a0 5b 66 80 24 00 00 00 mmal.....[f.$...
[  125.458515] vchiq: Sent Msg DATA(5) to mmal s:3 d:88 len:56
[  125.458595] vchiq: Rcvd Msg DATA(5) from mmal s:88 d:3 len:28
[  125.458618] vchiq: Rcvd: 00000000: 6d 6d 61 6c 0e 00 00 00 f4 82 3d 3f 24 00 00 00 mmal......=?$...
[  125.458669] vchiq: Sent: 00000000: 6d 6d 61 6c 0e 00 00 00 a0 5b 66 80 25 00 00 00 mmal.....[f.%...
[  125.458678] vchiq: Sent Msg DATA(5) to mmal s:3 d:88 len:56
[  125.458755] vchiq: Rcvd Msg DATA(5) from mmal s:88 d:3 len:28
[  125.458779] vchiq: Rcvd: 00000000: 6d 6d 61 6c 0e 00 00 00 f4 82 3d 3f 25 00 00 00 mmal......=?%...
[  125.458828] vchiq: Sent: 00000000: 6d 6d 61 6c 0e 00 00 00 6d 6d 61 6c 26 00 00 00 mmal....mmal&...
[  125.458837] vchiq: Sent Msg DATA(5) to mmal s:3 d:88 len:44
[  125.458916] vchiq: Rcvd Msg DATA(5) from mmal s:88 d:3 len:28
[  125.458940] vchiq: Rcvd: 00000000: 6d 6d 61 6c 0e 00 00 00 f4 82 3d 3f 26 00 00 00 mmal......=?&...
[  125.458989] vchiq: Sent: 00000000: 6d 6d 61 6c 0e 00 00 00 6d 6d 61 6c 27 00 00 00 mmal....mmal'...
[  125.458998] vchiq: Sent Msg DATA(5) to mmal s:3 d:88 len:44
[  125.459076] vchiq: Rcvd Msg DATA(5) from mmal s:88 d:3 len:28
[  125.459099] vchiq: Rcvd: 00000000: 6d 6d 61 6c 0e 00 00 00 f4 82 3d 3f 27 00 00 00 mmal......=?'...
[  125.459149] vchiq: Sent: 00000000: 6d 6d 61 6c 0e 00 00 00 a0 5b 66 80 28 00 00 00 mmal.....[f.(...
[  125.459158] vchiq: Sent Msg DATA(5) to mmal s:3 d:88 len:56
[  125.459233] vchiq: Rcvd Msg DATA(5) from mmal s:88 d:3 len:28
[  125.459256] vchiq: Rcvd: 00000000: 6d 6d 61 6c 0e 00 00 00 f4 82 3d 3f 28 00 00 00 mmal......=?(...
[  125.459306] vchiq: Sent: 00000000: 6d 6d 61 6c 0e 00 00 00 a0 5b 66 80 29 00 00 00 mmal.....[f.)...
[  125.459315] vchiq: Sent Msg DATA(5) to mmal s:3 d:88 len:56
[  125.459389] vchiq: Rcvd Msg DATA(5) from mmal s:88 d:3 len:28
[  125.459413] vchiq: Rcvd: 00000000: 6d 6d 61 6c 0e 00 00 00 f4 82 3d 3f 29 00 00 00 mmal......=?)...
[  125.459462] vchiq: Sent: 00000000: 6d 6d 61 6c 0e 00 00 00 a0 5b 66 80 2a 00 00 00 mmal.....[f.*...
[  125.459471] vchiq: Sent Msg DATA(5) to mmal s:3 d:88 len:56
[  125.459550] vchiq: Rcvd Msg DATA(5) from mmal s:88 d:3 len:28
[  125.459573] vchiq: Rcvd: 00000000: 6d 6d 61 6c 0e 00 00 00 f4 82 3d 3f 2a 00 00 00 mmal......=?*...
[  125.459623] vchiq: Sent: 00000000: 6d 6d 61 6c 0e 00 00 00 00 00 00 00 2b 00 00 00 mmal........+...
[  125.459632] vchiq: Sent Msg DATA(5) to mmal s:3 d:88 len:44
[  125.459708] vchiq: Rcvd Msg DATA(5) from mmal s:88 d:3 len:28
[  125.459731] vchiq: Rcvd: 00000000: 6d 6d 61 6c 0e 00 00 00 f4 82 3d 3f 2b 00 00 00 mmal......=?+...
[  125.459781] vchiq: Sent: 00000000: 6d 6d 61 6c 0e 00 00 00 6d 6d 61 6c 2c 00 00 00 mmal....mmal,...
[  125.459790] vchiq: Sent Msg DATA(5) to mmal s:3 d:88 len:44
[  125.459869] vchiq: Rcvd Msg DATA(5) from mmal s:88 d:3 len:28
[  125.459891] vchiq: Rcvd: 00000000: 6d 6d 61 6c 0e 00 00 00 f4 82 3d 3f 2c 00 00 00 mmal......=?,...
[  125.459940] vchiq: Sent: 00000000: 6d 6d 61 6c 0e 00 00 00 6d 6d 61 6c 2d 00 00 00 mmal....mmal-...
[  125.459949] vchiq: Sent Msg DATA(5) to mmal s:3 d:88 len:44
[  125.460026] vchiq: Rcvd Msg DATA(5) from mmal s:88 d:3 len:28
[  125.460051] vchiq: Rcvd: 00000000: 6d 6d 61 6c 0e 00 00 00 f4 82 3d 3f 2d 00 00 00 mmal......=?-...
[  125.460101] vchiq: Sent: 00000000: 6d 6d 61 6c 0e 00 00 00 a0 5b 66 80 2e 00 00 00 mmal.....[f.....
[  125.460109] vchiq: Sent Msg DATA(5) to mmal s:3 d:88 len:56
[  125.460187] vchiq: Rcvd Msg DATA(5) from mmal s:88 d:3 len:28
[  125.460210] vchiq: Rcvd: 00000000: 6d 6d 61 6c 0e 00 00 00 f4 82 3d 3f 2e 00 00 00 mmal......=?....
[  125.460260] vchiq: Sent: 00000000: 6d 6d 61 6c 0e 00 00 00 a0 5b 66 80 2f 00 00 00 mmal.....[f./...
[  125.460269] vchiq: Sent Msg DATA(5) to mmal s:3 d:88 len:56
[  125.460357] vchiq: Rcvd Msg DATA(5) from mmal s:88 d:3 len:28
[  125.460380] vchiq: Rcvd: 00000000: 6d 6d 61 6c 0e 00 00 00 f4 82 3d 3f 2f 00 00 00 mmal......=?/...
[  125.460442] vchiq: Sent: 00000000: 6d 6d 61 6c 0e 00 00 00 a0 5b 66 80 30 00 00 00 mmal.....[f.0...
[  125.460458] vchiq: Sent Msg DATA(5) to mmal s:3 d:88 len:56
[  125.460541] vchiq: Rcvd Msg DATA(5) from mmal s:88 d:3 len:28
[  125.460563] vchiq: Rcvd: 00000000: 6d 6d 61 6c 0e 00 00 00 f4 82 3d 3f 30 00 00 00 mmal......=?0...
[  125.460611] vchiq: Sent: 00000000: 6d 6d 61 6c 0e 00 00 00 00 00 00 00 31 00 00 00 mmal........1...
[  125.460627] vchiq: Sent Msg DATA(5) to mmal s:3 d:88 len:44
[  125.460712] vchiq: Rcvd Msg DATA(5) from mmal s:88 d:3 len:28
[  125.460734] vchiq: Rcvd: 00000000: 6d 6d 61 6c 0e 00 00 00 f4 82 3d 3f 31 00 00 00 mmal......=?1...
[  125.460785] vchiq: Sent: 00000000: 6d 6d 61 6c 0e 00 00 00 00 00 00 00 32 00 00 00 mmal........2...
[  125.460800] vchiq: Sent Msg DATA(5) to mmal s:3 d:88 len:44
[  125.460882] vchiq: Rcvd Msg DATA(5) from mmal s:88 d:3 len:28
[  125.460904] vchiq: Rcvd: 00000000: 6d 6d 61 6c 0e 00 00 00 f4 82 3d 3f 32 00 00 00 mmal......=?2...
[  125.460956] vchiq: Sent: 00000000: 6d 6d 61 6c 0e 00 00 00 03 50 00 00 33 00 00 00 mmal.....P..3...
[  125.460975] vchiq: Sent Msg DATA(5) to mmal s:3 d:88 len:56
[  125.461055] vchiq: Rcvd Msg DATA(5) from mmal s:88 d:3 len:28
[  125.461076] vchiq: Rcvd: 00000000: 6d 6d 61 6c 0e 00 00 00 f4 82 3d 3f 33 00 00 00 mmal......=?3...
[  125.461126] vchiq: Sent: 00000000: 6d 6d 61 6c 0e 00 00 00 03 50 00 00 34 00 00 00 mmal.....P..4...
[  125.461141] vchiq: Sent Msg DATA(5) to mmal s:3 d:88 len:56
[  125.461221] vchiq: Rcvd Msg DATA(5) from mmal s:88 d:3 len:28
[  125.461242] vchiq: Rcvd: 00000000: 6d 6d 61 6c 0e 00 00 00 f4 82 3d 3f 34 00 00 00 mmal......=?4...
[  125.461293] vchiq: Sent: 00000000: 6d 6d 61 6c 0e 00 00 00 00 00 00 00 35 00 00 00 mmal........5...
[  125.461302] vchiq: Sent Msg DATA(5) to mmal s:3 d:88 len:68
[  125.461385] vchiq: Rcvd Msg DATA(5) from mmal s:88 d:3 len:28
[  125.461408] vchiq: Rcvd: 00000000: 6d 6d 61 6c 0e 00 00 00 f4 82 3d 3f 35 00 00 00 mmal......=?5...
[  125.463535] vchiq: Sent: 00000000: 6d 6d 61 6c 0e 00 00 00 00 00 00 00 36 00 00 00 mmal........6...
[  125.463550] vchiq: Sent Msg DATA(5) to mmal s:3 d:88 len:52
[  125.463641] vchiq: Rcvd Msg DATA(5) from mmal s:88 d:3 len:28
[  125.463668] vchiq: Rcvd: 00000000: 6d 6d 61 6c 0e 00 00 00 f4 82 3d 3f 36 00 00 00 mmal......=?6...
[  125.463743] vchiq: Sent: 00000000: 6d 6d 61 6c 0e 00 00 00 6d 6d 61 6c 37 00 00 00 mmal....mmal7...
[  125.463752] vchiq: Sent Msg DATA(5) to mmal s:3 d:88 len:52
[  125.463834] vchiq: Rcvd Msg DATA(5) from mmal s:88 d:3 len:28
[  125.463860] vchiq: Rcvd: 00000000: 6d 6d 61 6c 0e 00 00 00 f4 82 3d 3f 37 00 00 00 mmal......=?7...
[  125.464399] vchiq: Sent: 00000000: 6d 6d 61 6c 0e 00 00 00 6d 6d 61 6c 38 00 00 00 mmal....mmal8...
[  125.464410] vchiq: Sent Msg DATA(5) to mmal s:3 d:88 len:44
[  125.464500] vchiq: Rcvd Msg DATA(5) from mmal s:88 d:3 len:28
[  125.464526] vchiq: Rcvd: 00000000: 6d 6d 61 6c 0e 00 00 00 f4 82 3d 3f 38 00 00 00 mmal......=?8...
[  125.464589] vchiq: Sent: 00000000: 6d 6d 61 6c 0e 00 00 00 6d 6d 61 6c 39 00 00 00 mmal....mmal9...
[  125.464598] vchiq: Sent Msg DATA(5) to mmal s:3 d:88 len:44
[  125.464678] vchiq: Rcvd Msg DATA(5) from mmal s:88 d:3 len:28
[  125.464703] vchiq: Rcvd: 00000000: 6d 6d 61 6c 0e 00 00 00 f4 82 3d 3f 39 00 00 00 mmal......=?9...
[  125.464759] vchiq: Sent: 00000000: 6d 6d 61 6c 0e 00 00 00 6d 6d 61 6c 3a 00 00 00 mmal....mmal:...
[  125.464768] vchiq: Sent Msg DATA(5) to mmal s:3 d:88 len:44
[  125.464847] vchiq: Rcvd Msg DATA(5) from mmal s:88 d:3 len:28
[  125.464870] vchiq: Rcvd: 00000000: 6d 6d 61 6c 0e 00 00 00 f4 82 3d 3f 3a 00 00 00 mmal......=?:...
[  125.464926] vchiq: Sent: 00000000: 6d 6d 61 6c 0e 00 00 00 40 00 00 00 3b 00 00 00 mmal....@...;...
[  125.464936] vchiq: Sent Msg DATA(5) to mmal s:3 d:88 len:44
[  125.465011] vchiq: Rcvd Msg DATA(5) from mmal s:88 d:3 len:28
[  125.465035] vchiq: Rcvd: 00000000: 6d 6d 61 6c 0e 00 00 00 f4 82 3d 3f 3b 00 00 00 mmal......=?;...
[  125.465088] vchiq: Sent: 00000000: 6d 6d 61 6c 0e 00 00 00 40 00 00 00 3c 00 00 00 mmal....@...<...
[  125.465098] vchiq: Sent Msg DATA(5) to mmal s:3 d:88 len:44
[  125.465180] vchiq: Rcvd Msg DATA(5) from mmal s:88 d:3 len:28
[  125.465204] vchiq: Rcvd: 00000000: 6d 6d 61 6c 0e 00 00 00 f4 82 3d 3f 3c 00 00 00 mmal......=?<...
[  125.465255] vchiq: Sent: 00000000: 6d 6d 61 6c 0e 00 00 00 40 00 00 00 3d 00 00 00 mmal....@...=...
[  125.465271] vchiq: Sent Msg DATA(5) to mmal s:3 d:88 len:44
[  125.465351] vchiq: Rcvd Msg DATA(5) from mmal s:88 d:3 len:28
[  125.465374] vchiq: Rcvd: 00000000: 6d 6d 61 6c 0e 00 00 00 f4 82 3d 3f 3d 00 00 00 mmal......=?=...
[  125.465431] vchiq: Sent: 00000000: 6d 6d 61 6c 0e 00 00 00 40 00 00 00 3e 00 00 00 mmal....@...>...
[  125.465449] vchiq: Sent Msg DATA(5) to mmal s:3 d:88 len:44
[  125.465524] vchiq: Rcvd Msg DATA(5) from mmal s:88 d:3 len:28
[  125.465549] vchiq: Rcvd: 00000000: 6d 6d 61 6c 0e 00 00 00 f4 82 3d 3f 3e 00 00 00 mmal......=?>...
[  125.465607] vchiq: Sent: 00000000: 6d 6d 61 6c 0e 00 00 00 40 00 00 00 3f 00 00 00 mmal....@...?...
[  125.465628] vchiq: Sent Msg DATA(5) to mmal s:3 d:88 len:44
[  125.465709] vchiq: Rcvd Msg DATA(5) from mmal s:88 d:3 len:28
[  125.465731] vchiq: Rcvd: 00000000: 6d 6d 61 6c 0e 00 00 00 f4 82 3d 3f 3f 00 00 00 mmal......=??...
[  125.465781] vchiq: Sent: 00000000: 6d 6d 61 6c 0e 00 00 00 40 00 00 00 40 00 00 00 mmal....@...@...
[  125.465790] vchiq: Sent Msg DATA(5) to mmal s:3 d:88 len:44
[  125.465868] vchiq: Rcvd Msg DATA(5) from mmal s:88 d:3 len:28
[  125.465892] vchiq: Rcvd: 00000000: 6d 6d 61 6c 0e 00 00 00 f4 82 3d 3f 40 00 00 00 mmal......=?@...
[  125.465947] vchiq: Sent: 00000000: 6d 6d 61 6c 0e 00 00 00 40 00 00 00 41 00 00 00 mmal....@...A...
[  125.465957] vchiq: Sent Msg DATA(5) to mmal s:3 d:88 len:44
[  125.466040] vchiq: Rcvd Msg DATA(5) from mmal s:88 d:3 len:28
[  125.466066] vchiq: Rcvd: 00000000: 6d 6d 61 6c 0e 00 00 00 f4 82 3d 3f 41 00 00 00 mmal......=?A...
[  125.466116] vchiq: Sent: 00000000: 6d 6d 61 6c 0e 00 00 00 40 00 00 00 42 00 00 00 mmal....@...B...
[  125.466125] vchiq: Sent Msg DATA(5) to mmal s:3 d:88 len:44
[  125.466207] vchiq: Rcvd Msg DATA(5) from mmal s:88 d:3 len:28
[  125.466230] vchiq: Rcvd: 00000000: 6d 6d 61 6c 0e 00 00 00 f4 82 3d 3f 42 00 00 00 mmal......=?B...
[  125.466284] vchiq: Sent: 00000000: 6d 6d 61 6c 0e 00 00 00 6d 6d 61 6c 43 00 00 00 mmal....mmalC...
[  125.466293] vchiq: Sent Msg DATA(5) to mmal s:3 d:88 len:44
[  125.466373] vchiq: Rcvd Msg DATA(5) from mmal s:88 d:3 len:28
[  125.466396] vchiq: Rcvd: 00000000: 6d 6d 61 6c 0e 00 00 00 f4 82 3d 3f 43 00 00 00 mmal......=?C...
[  125.466454] vchiq: Sent: 00000000: 6d 6d 61 6c 0e 00 00 00 00 00 00 00 44 00 00 00 mmal........D...
[  125.466462] vchiq: Sent Msg DATA(5) to mmal s:3 d:88 len:44
[  125.466544] vchiq: Rcvd Msg DATA(5) from mmal s:88 d:3 len:28
[  125.466569] vchiq: Rcvd: 00000000: 6d 6d 61 6c 0e 00 00 00 f4 82 3d 3f 44 00 00 00 mmal......=?D...
[  125.466624] vchiq: Sent: 00000000: 6d 6d 61 6c 0e 00 00 00 6d 6d 61 6c 45 00 00 00 mmal....mmalE...
[  125.466633] vchiq: Sent Msg DATA(5) to mmal s:3 d:88 len:44
[  125.466724] vchiq: Rcvd Msg DATA(5) from mmal s:88 d:3 len:28
[  125.466749] vchiq: Rcvd: 00000000: 6d 6d 61 6c 0e 00 00 00 f4 82 3d 3f 45 00 00 00 mmal......=?E...
[  125.466803] vchiq: Sent: 00000000: 6d 6d 61 6c 0e 00 00 00 00 00 00 00 46 00 00 00 mmal........F...
[  125.466811] vchiq: Sent Msg DATA(5) to mmal s:3 d:88 len:48
[  125.466905] vchiq: Rcvd Msg DATA(5) from mmal s:88 d:3 len:28
[  125.466929] vchiq: Rcvd: 00000000: 6d 6d 61 6c 0e 00 00 00 f4 82 3d 3f 46 00 00 00 mmal......=?F...
[  125.466985] vchiq: Sent: 00000000: 6d 6d 61 6c 0e 00 00 00 00 00 00 00 47 00 00 00 mmal........G...
[  125.466995] vchiq: Sent Msg DATA(5) to mmal s:3 d:88 len:48
[  125.467081] vchiq: Rcvd Msg DATA(5) from mmal s:88 d:3 len:28
[  125.467105] vchiq: Rcvd: 00000000: 6d 6d 61 6c 0e 00 00 00 f4 82 3d 3f 47 00 00 00 mmal......=?G...
[  125.467135] bcm2835-v4l2: scene mode selected 0, was 0
[  125.467166] vchiq: Sent: 00000000: 6d 6d 61 6c 0e 00 00 00 6d 6d 61 6c 48 00 00 00 mmal....mmalH...
[  125.467175] vchiq: Sent Msg DATA(5) to mmal s:3 d:88 len:44
[  125.467262] vchiq: Rcvd Msg DATA(5) from mmal s:88 d:3 len:28
[  125.467286] vchiq: Rcvd: 00000000: 6d 6d 61 6c 0e 00 00 00 f4 82 3d 3f 48 00 00 00 mmal......=?H...
[  125.467616] bcm2835-v4l2: V4L2 device registered as video0 - stills mode > 1280x720
[  125.467653] vchiq: Sent: 00000000: 6d 6d 61 6c 09 00 00 00 40 3d 36 ba 49 00 00 00 mmal....@=6.I...
[  125.467662] vchiq: Sent Msg DATA(5) to mmal s:3 d:88 len:304
[  125.467821] vchiq: Rcvd Msg PADDING(0) from ???? s:0 d:0 len:104
[  125.467846] vchiq: Rcvd: 00000000: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 ................
[  125.467857] vchiq: Rcvd Msg DATA(5) from mmal s:88 d:3 len:316
[  125.467880] vchiq: Rcvd: 00000000: 6d 6d 61 6c 09 00 00 00 f4 82 3d 3f 49 00 00 00 mmal......=?I...
[  125.467947] vchiq: Sent: 00000000: 6d 6d 61 6c 08 00 00 00 00 00 00 00 4a 00 00 00 mmal........J...
[  125.467957] vchiq: Sent Msg DATA(5) to mmal s:3 d:88 len:36
[  125.468018] vchiq: Rcvd Msg DATA(5) from mmal s:88 d:3 len:316
[  125.468041] vchiq: Rcvd: 00000000: 6d 6d 61 6c 08 00 00 00 f4 82 3d 3f 4a 00 00 00 mmal......=?J...
[  125.468109] vchiq: Sent: 00000000: 6d 6d 61 6c 09 00 00 00 03 50 00 00 4b 00 00 00 mmal.....P..K...
[  125.468119] vchiq: Sent Msg DATA(5) to mmal s:3 d:88 len:304
[  125.468248] vchiq: Rcvd Msg DATA(5) from mmal s:88 d:3 len:316
[  125.468273] vchiq: Rcvd: 00000000: 6d 6d 61 6c 09 00 00 00 f4 82 3d 3f 4b 00 00 00 mmal......=?K...
[  125.468334] vchiq: Sent: 00000000: 6d 6d 61 6c 08 00 00 00 00 00 00 00 4c 00 00 00 mmal........L...
[  125.468344] vchiq: Sent Msg DATA(5) to mmal s:3 d:88 len:36
[  125.468403] vchiq: Rcvd Msg DATA(5) from mmal s:88 d:3 len:316
[  125.468426] vchiq: Rcvd: 00000000: 6d 6d 61 6c 08 00 00 00 f4 82 3d 3f 4c 00 00 00 mmal......=?L...
[  125.468491] vchiq: Sent: 00000000: 6d 6d 61 6c 0a 00 00 00 30 00 00 00 4d 00 00 00 mmal....0...M...
[  125.468500] vchiq: Sent Msg DATA(5) to mmal s:3 d:88 len:44
[  125.468580] vchiq: Rcvd Msg DATA(5) from mmal s:88 d:3 len:28
[  125.468605] vchiq: Rcvd: 00000000: 6d 6d 61 6c 0a 00 00 00 f4 82 3d 3f 4d 00 00 00 mmal......=?M...
[  125.468665] vchiq: Sent: 00000000: 6d 6d 61 6c 09 00 00 00 6d 6d 61 6c 4e 00 00 00 mmal....mmalN...
[  125.468687] vchiq: Sent Msg DATA(5) to mmal s:3 d:88 len:304
[  125.468811] vchiq: Rcvd Msg DATA(5) from mmal s:88 d:3 len:316
[  125.468836] vchiq: Rcvd: 00000000: 6d 6d 61 6c 09 00 00 00 f4 82 3d 3f 4e 00 00 00 mmal......=?N...
[  125.468895] vchiq: Sent: 00000000: 6d 6d 61 6c 08 00 00 00 00 00 00 00 4f 00 00 00 mmal........O...
[  125.468906] vchiq: Sent Msg DATA(5) to mmal s:3 d:88 len:36
[  125.468965] vchiq: Rcvd Msg DATA(5) from mmal s:88 d:3 len:316
[  125.468989] vchiq: Rcvd: 00000000: 6d 6d 61 6c 08 00 00 00 f4 82 3d 3f 4f 00 00 00 mmal......=?O...
[  125.469051] vchiq: Sent: 00000000: 6d 6d 61 6c 06 00 00 00 30 00 00 00 50 00 00 00 mmal....0...P...
[  125.469069] vchiq: Sent Msg DATA(5) to mmal s:3 d:88 len:28
[  125.473193] vchiq: Rcvd Msg DATA(5) from mmal s:88 d:3 len:28
[  125.473226] vchiq: Rcvd: 00000000: 6d 6d 61 6c 06 00 00 00 f4 82 3d 3f 50 00 00 00 mmal......=?P...
[  125.473288] bcm2835-v4l2: Broadcom 2835 MMAL video capture ver 0.0.2 loaded.
[  134.630326] nfs: server 10.3.14.8 not responding, still trying
[  137.990337] lan78xx 1-1.1.1:1.0 eth0: Failed to read stat ret = 0xffffff92
[  152.790326] nfs: server 10.3.14.8 not responding, still trying
[  155.910319] lan78xx 1-1.1.1:1.0 eth0: Failed to read stat ret = 0xffffff92

Note the (presumably fatal) dwc_otg messages, and the subsequent NFS death.

@jonshouse1
Copy link
Author

It's odd as there isn't anything fundamentally different between SD card and network booting.
I am not a kernel hacker for linux but I do write embedded firmware, for my 2c worth I suspect it is either an assumption about ISR order or frequency.

@jonshouse1
Copy link
Author

Any update on this ?

I did an rpi-update, now running
Linux raspberrypi 4.14.37-v7+ #1111 SMP Thu Apr 26 13:56:59 BST 2018 armv7l GNU/Linux

This is much the same, except it returns the prompt before crashing after "modprobe bcm2835-v4l2" . PS this new kernel/firmware version is slightly less reliable NFS booting than before. Sometimes stops on the IP details summary and fails to continue..... odd ...

Thanks,
Jon

@jonshouse1
Copy link
Author

18 days zero comments. Am I correct that the issue is within the Broadcom binary b******ks (tm)? I am assuming this is not an issue I can investigate ?

@6by9
Copy link
Contributor

6by9 commented May 11, 2018

Sorry, busy on other issues/tasks. It got an initial triage and is now in the queue to investigate.

Am I correct that the issue is within the Broadcom binary b******ks (tm)? I am assuming this is not an issue I can investigate ?

Incorrect as noted in #2335 (comment)
Anything calling bcm_host_init before the bcm2835-v4l2 module is loaded appears to resolve the issue. Source for bcm_host_init is in the normal place for userland code if you wished to investigate exactly which bit is making the module happy.

@jonshouse1
Copy link
Author

jonshouse1 commented May 11, 2018

if you wished to investigate exactly which bit is making the module happy

Ok, I will have a look, what is the best place to browse the source of the specific RPI shipped version of the "bcm2835-v4l2" module ?

I don't know how the vc code interacts with the kernel code.
I note that bcm_host_init() is protected from multiple init calls "if (initted) return;" so a hack (rather than a true fix) would be to arrange it that the module called bcm_host_init() before it started 'real work' and see if that improves it. I need to read up on getting enough of a build environment to modify the module.....

@jonshouse1
Copy link
Author

// gcc bcmhi.c -I/opt/vc/include -L/opt/vc/lib -lbcm_host -o bcmhi 

int main ()
{
	bcm_host_init();
}

Compiled the following as "bcmhi", when run before the modprobe on the NFS booted machine the module loads ok.

I noticed this on the debug output above. Doesn't the CSI interface depend on an ISR resident in the vc code ?

[ 123.283885] WARN::dwc_otg_hcd_handle_hc_fsm:2458: Unexpected IRQ state on FSM transaction:dev_addr=4 ep=2 fsm=6, hcint=0x00000002

Thanks,
Jon

@6by9
Copy link
Contributor

6by9 commented May 11, 2018

Compiled the following as "bcmhi", when run before the modprobe on the NFS booted machine the module loads ok.

OK, so confirmed as a duplicate of #2335 then.

I noticed this on the debug output above. Doesn't the CSI interface depend on an ISR resident in the vc code ?
[ 123.283885] WARN::dwc_otg_hcd_handle_hc_fsm:2458: Unexpected IRQ state on FSM transaction:dev_addr=4 ep=2 fsm=6, hcint=0x00000002

??! How did you get from an error message from the USB driver (dwc_otg) to worrying over interrupts from the camera?
As it happens the ARM and VPU have independent interrupt controllers and almost all interrupt lines are presented to both, so the ARM can do as it pleases there.

@jonshouse1
Copy link
Author

jonshouse1 commented May 11, 2018

"ARM and VPU have independent interrupt controllers"
Having a slow day, yes I see what you are saying, . I can't clearly see what the VPU is actually doing, or at the moment even work out when I pass into the binary open code. For example bcm_host_init() calls vchiq_initialise(), I assume that is as far down as I see along that path as I cant find source for vchiq_initialise()?

@6by9
Copy link
Contributor

6by9 commented May 11, 2018

I assume that is as far down as I see along that path as I cant find source for vchiq_initialise()?

https://github.com/raspberrypi/userland/blob/master/interface/vchiq_arm/vchiq_lib.c#L161

Although the first stage would be to copy/paste the implementation of bcm_host_init into your app to see how far through you need to go to make the module loading work correctly. Once you've done that, then start following the last required call down (or just report back as you'll have saved us a good half hour or so of debug).

@jonshouse1
Copy link
Author

jonshouse1 commented May 11, 2018

http://jonshouse.co.uk/bcmhi.tar.gz

I copied some bits around, no makefile "./compile" generates a binary "bcmhi"

In bcm_host.c i modified bcm_host_init(), adding a printf.

I move the return down the function one call at a time re-booting between each attempt, reached pretty much the end of the function before the modprobe worked.

Output looked liked this:


 root@raspberrypi:/bcmhi# ./bcmhi 
 did vcos init()
 did vchiq_initialise()
 did vchi_initialise()
 did vchi_create_connection()
 did vchi_connect() 
 did vc_vchi_gencmd_init()
 did vc_vchi_dispmanx_init()
 did vc_vchi_tv_init()
 did vc_vchi_cec_init()
 did vc_gencmd()
 root@raspberrypi:/bcmhi# modprobe bcm2835-v4l2
 root@raspberrypi:/bcmhi# 

Not sure if that helps, I cant see source for vc_gencmd() so I assume that is as far as I can follow that line ?

@jonshouse1
Copy link
Author

Found vc_gencmd() ...
https://github.com/raspberrypi/userland/blob/a1b89e91f393c7134b4cdc36431f863bb3333163/interface/vmcs_host/vc_vchi_gencmd.c

seems github search does not show the function definition in preference to callers... will egrerp -r locally instead from now on, me bad ...

@6by9
Copy link
Contributor

6by9 commented May 24, 2018

I've finally had a chance to dig into this. The minimum set of stuff from bcm_host_init is

   vchi_connect(&global_connection, 1, global_initialise_instance);
  
   vc_vchi_gencmd_init (global_initialise_instance, &global_connection, 1);

   if ( success == 0 )
   {
      success = vc_gencmd( response, sizeof(response), "set_vll_dir /sd/vlls" );
      vcos_assert( success == 0 );
   }
}

The camera component does query VLLs, so I suspect that something in the internal "filesystem" on the VPU is blowing up due to not having the VLL directory set sensibly. I'll trace it further in the firmware now.

@6by9
Copy link
Contributor

6by9 commented May 29, 2018

Firmware patch created to fix this issue. It'll be reviewed internally, but I'd expect it to be in the next rpi-update release.

popcornmix added a commit to raspberrypi/firmware that referenced this issue Jun 7, 2018
…era stages

See: raspberrypi/linux#2528

firmware: bootcode: Force an I2C stop as a reset
firmware: power: Ensure at least 2ms between writes to the PMIC regs
firmware: power: Add 3ms threshold
firmware: power: Reduce i2c speed of pmic to 100kHz
popcornmix added a commit to Hexxeh/rpi-firmware that referenced this issue Jun 7, 2018
…era stages

See: raspberrypi/linux#2528

firmware: bootcode: Force an I2C stop as a reset
firmware: power: Ensure at least 2ms between writes to the PMIC regs
firmware: power: Add 3ms threshold
firmware: power: Reduce i2c speed of pmic to 100kHz
@6by9
Copy link
Contributor

6by9 commented Jun 27, 2018

Workaround was merged 5 June, released via rpi-update 7 June.
@jonshouse1 Please test, otherwise this issue will get closed in 30 days.

@JamesH65
Copy link
Contributor

This issue will be closed within 30 days unless further interactions are posted. If you wish this issue to remain open, please add a comment. A closed issue may be reopened if requested.

@JamesH65 JamesH65 added the Close within 30 days Issue will be closed within 30 days unless requested to stay open label Jun 27, 2018
@jonshouse1
Copy link
Author

jonshouse1 commented Jun 27, 2018

I am trying to figure out how to update the NFS root image without backtracking to the original SD card image then copying it all back over.

I get this super crap error (invalid hash of what?, from where? referenced by what ?)

root@raspberrypicamera:~# rpi-update 
 *** Raspberry Pi firmware updater by Hexxeh, enhanced by AndrewS and Dom
 *** Performing self-update
 *** Relaunching after update
 *** Raspberry Pi firmware updater by Hexxeh, enhanced by AndrewS and Dom
 *** Invalid hash given

@6by9
Copy link
Contributor

6by9 commented Jun 27, 2018

You're on a network booted system so need to update the files that your TFTP server is handing out.

Go to https://github.com/Hexxeh/rpi-firmware, download the start*.elf files and fixup.* files, and put them in the directory that your TFTP server is using. Reboot the Pi. The firmware should now all be updated, and hopefully the issue resolved.

@pelwell
Copy link
Contributor

pelwell commented Jun 27, 2018

Alternatively you can (if your TFTP server is sharing its files) mount the TFTP server directory for your Pi on /boot and use rpi-update as usual.

@jonshouse1
Copy link
Author

jonshouse1 commented Jun 27, 2018

"You're on a network booted system so need to update the files that your TFTP server is handing out."
Yes, I know :-)

I login to the NFS booted Pi via ssh - as default it is read only

I issue
# mount -o remount rw /

Check it

root@raspberrypicamera:~# ls >x
root@raspberrypicamera:~# rm x

Yep, it is read/write ok.

My NFS root has a "/boot" this is the same contents as the firmware directory the Pi booted from
(on the NFS server itself)
root@mail:/disks/vol1/tftpboot/rpi_cctv/boot# cp -av ../../25bcbfa6/* .

Now rpi-update can see a normal read/write "/" and a true representation of "/boot" - in the past I simply ran rpi-update at this point and all was good, then copied the firmware back into the serial number directory.

@jonshouse1
Copy link
Author

"Go to https://github.com/Hexxeh/rpi-firmware, download the start*.elf files and fixup.* files, and put them in the directory that your TFTP server is using"
Thanks, I will give that a go.... in case the overlays have changed I will try replacing all files with a new one and copying back config.txt and cmdline.txt as I think those are the only user settings ?

@pelwell
Copy link
Contributor

pelwell commented Jun 27, 2018

One thing to be aware of is that this won't update the bootcode.bin downloaded by the bootrom, which doesn't support the serial number subdirectories,

@jonshouse1
Copy link
Author

One thing to be aware of is that this won't update the bootcode.bin downloaded by the bootrom, which doesn't support the serial number subdirectories,

Sorry, I don't understand. Isn't the bootcode.bin the same binary however it is loaded by the Pi... what does not support the serial number subdirectories?, you have lost me at this point.

@pelwell
Copy link
Contributor

pelwell commented Jun 27, 2018

When the boot ROM downloads bootcode.bin from the TFTP server (as a 3B+ can when booting with no SD card) it only looks for bootcode.bin, not <serial>/bootcode.bin, despite the fact that bootcode.bin itself will then search for <serial>/start.elf etc. This isn't a problem because the same image will run on all models and will be backwards compatible, but it may catch you out if you thought you were updating it when actually you were just overwriting <serial>/bootcode.bin.

@jonshouse1
Copy link
Author

"when actually you were just overwriting /bootcode.bin."
Great, I understand now, thanks :-)

Glad you mentioned that, I was looking at the ftfboot directory just now thinking I must delete some of these stray files....

@jonshouse1
Copy link
Author

Yay ...

Thanks :-)

root@raspberrypicamera:~# modprobe bcm2835-v4l2 
root@raspberrypicamera:~# /opt/vc/bin/vcgencmd version
Jun 21 2018 14:07:17 
Copyright (c) 2012 Broadcom
version 8885266d85a7c3c03894fcb03c9724020f9cd77e (clean) (release)

@jonshouse1
Copy link
Author

PS I uploaded the camera client/server code to github for safe keeping, bit rough at the moment, but works ok. It looks static on the video but is updating 14 frames a second.

My next job is top try and figure out how to write my date/time stamp over the camera frame then have the Pi jpeg encode the result. At the moment I use v4l to read the frame as YUV, convert to RGB, overlay the text then jpeg encode and send the image to the server.

Linux desktop viewer.
https://www.youtube.com/watch?v=ilA25ho_u-k&feature=youtu.be

The code, server, client and desktop apps.
https://github.com/jonshouse1/jcamsys

@6by9
Copy link
Contributor

6by9 commented Jun 27, 2018

My next job is top try and figure out how to write my date/time stamp over the camera frame then have the Pi jpeg encode the result. At the moment I use v4l to read the frame as YUV, convert to RGB, overlay the text then jpeg encode and send the image to the server.

Eek! Why do people hate YUV so much?
The camera can spit out RGB in a number of flavours (conversion done in vector code on the VPU), so no need to do the conversion in your app.
Hardware accelerated JPEG encode requires YUV, so it has to convert back from your RGB frame. Memory says there are some mechanisms for JPEG to contain RGB, but they are relatively uncommon.

It's a slight shame that you chose to use V4L2, as the camera subsystem can do basic annotations, as demonstrated in https://www.youtube.com/watch?v=WnnKrVSMbng. They're always top and centre at the moment as I haven't had the inclination to add the plumbing to move it around.

@jonshouse1
Copy link
Author

It's a slight shame that you chose to use V4L2, as the camera subsystem can do basic annotations

Nice demo video :-)

I have an RPI specific version of the camera code, that use v4l at the moment but can work in any way the Pi is happy with. It uses memory mapped I/O to read the state of the IR light level and to toggle the IRCUT filter on the camera module I am using, so it is non portable at that point:

https://github.com/jonshouse1/jcamsys/tree/master/jcamsys_camera_rpi/jcamsys_camera_rpi_v0.4

What I really need from an API is just a way to scribble into the framebuffer between the camera capture and some form of hrdware Jpeg encode. Does any API exist for my to plug into the YUV buffer and still let the Pi hardware encode the jpeg. I did look for demos/code and did not come up with a great deal.

I could not find any good examples of encoding a camera jpeg on the Pi video engine for example, I only want one jpeg at a time as I need to decide to send it or drop it depending on network conditions. I am using TCP and cant afford for the buffer to bloat to the point it becomes non real-time.

As for RGB24 rather than YUV, it's mostly because I can work with RGB in my head hence that is what most of my code references, I can probably work with YUV but only with several google pages open ;-)

@jonshouse1
Copy link
Author

It has been so long since I looked at this, I was wrong, the generic V4l code uses YUV if opening the device for RGB fails OR (and it is an important or) the size of the RGB image is wrong. Seems V4l has a fault on some cameras, claims it opens in RGB but does not, in that case the code 'falls back' to YUV and adds a conversion to RGB.
The code overlaying the text is RGB though and the Jpeg encode is via libjpeg rather than the v4l API.
See lines 672+

Video of configuration tool, changes server settings and also passes settings to any connected cameras.
https://youtu.be/8yGgJwwZ700

mkreisl added a commit to xbianonpi/xbian-package-firmware that referenced this issue Jul 23, 2018
… fixes:

- firmware: config: Add gpio command
  See: #955

- firmware: hat_lib: Only probe HAT EEPROM if ID pins are inputs

- firmware: Added a arm_display_kick function

- firmware: Possible fix for HDMI audio pause
  See: #547

- firmware: arm_loader: Always set the turbo frequencies immediately
  See: #956

- firmware: platform: Partial revert for eemc clock change for slice
  See: https://forum.libreelec.tv/thread/11930-libreelec-8-2-4-causes-slice-3-to-hang/

- firmware: clockman: Don't use OSC for pixel clock
  See: https://www.raspberrypi.org/forums/viewtopic.php?f=29&t=24679&start=150#p1297298

- firmware: config: gpio - Allow pn (pull none) as alternative to np (no pull)

- firmware: arm_loader: Use a wrapper to set clocks either through turbo or non-turbo interfaces
  See: #967

- firmware: platform: Allow vec pll to be adjusted
  See: #960

- firmware: platform: Pi3 B+ reduce sdram freq to 450 while investigations are ongoing
  See: https://www.raspberrypi.org/forums/viewtopic.php?f=28&t=208821

- firmware: arm_loader: Allow hdmi_ignore_composite to disable any display initialisation
  See: raspberrypi/userland#447

- firmware: Add aphy and dphy slew and drive register controls

- firmware: Extra reg writes to ensure the LCD display starts up at 800 wide

- firmware: platform: Lower temperature thresholds for extra pips to 50/60

- firmware: video_encode: Add support for YVU420Planar and YVU420SemiPlanar
- firmware: video_decode: Support YV12, NV12, and NV21 output
- firmware: video_decode: Support reporting colour space
- firmware: IL rawcam: Fix copy/paste error on timing setup
- firmware: MMAL: Populate buffer header TYPE_SPECIFIC fields

- firmware: video_encode: Filter the list of encoders based on variant

- firmware: mmal: Relax requirement on a buffer in mmal_port_send_buffer

- firmware: platform: avs: Also apply chicken bits to boost voltage

- firmware: Match phy setup same as bootcode for device mode initialisation

- firmware: Add logging_messages to UART

- bootcode: Fix 3B+ bootcode.bin only booting

- firmware: vc_image: vc_image_fill_yuv_uv sometimes overfilled the first column
  See: raspberrypi/userland#465

- firmware: arm_loader: Add SET_NOTIFY_REBOOT message
  See: #968

- firmware: gencmd: Report temperature with read_ring_osc values

- firmware: mmal_ril: Correct portdef assignment for video.eColorFormat
- firmware: variants: Add TGA and PPM codecs
- firmware: imx219: Fix exposure calcs for rounding down

- firmware: sdram: Remove [ad]phy_drv_slew logging spam

- firmware: sdram: Reduce address skew from -10 to -5

- firmware: platform: Avoid improving the schmoo on Pi3+
- firmware: platform: Latest AVS rules
- firmware: sdram: Increase read/write latency for higher sdram frequencies

- firmware: power: Add boot-time 3b+ PMIC register logging
- firmware: power: Continue to probe PMIC after error

- revert: sdram: Reduce address skew from -10 to -5
  See: https://forum.kodi.tv/showthread.php?tid=298461&pid=2740277#pid2740277

- firmware: variant: Disable custom_preproc and focus_stats_preproc camera stages
  See: raspberrypi/linux#2528

- firmware: bootcode: Force an I2C stop as a reset
- firmware: power: Ensure at least 2ms between writes to the PMIC regs
- firmware: power: Add 3ms threshold
- firmware: power: Reduce i2c speed of pmic to 100kHz

- firmware: dtoverlay: More "reg" and "name" support

- firmware: imx219: Updates for production test

- firmware: arm_loader: Update NOTIFY_REBOOT to reset the GPIO expander
  See: #968

- firmware: Allow selection of DSI port for LCD

- firmware: pwm_sdm: fix an edge case when reading back DMA source addresses

- firmware: pwm_sdm: fix write handle refcounting
  See: raspberrypi/linux#2587

- firmware: arm_dt: Protect against seg-fault when dt failed to load

- firmware: isp: Alter logging level for buffer size errors
- firmware: isp: Return output buffers that are too small
- firmware: video_encode: Integrate the ISP for format conversion
- firmware: mmal: Populate buffer->type->video.flags field
- firmware: image_fx: Apply interlacing flags from the plugin to output frames

- firmware: isp: IL compatibility and alignment tweaks
- firmware: IL ISP: Use vc_image instead of reworking own stride checking
- firmware: isp: Minor clean ups
- firmware: dispmanx: Complete the format strings for dispmanx_parse_list
- firmware: IL ISP: Use vc_image instead of reworking own stride checking
- firmware: MMAL/IL: Add support for components to report alignment requirements
@JamesH65 JamesH65 removed the Close within 30 days Issue will be closed within 30 days unless requested to stay open label Aug 31, 2018
@JamesH65
Copy link
Contributor

Closing this issue as questions answered/issue resolved.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

4 participants