In my previous post, I covered the hardware initialization tasks as they appear on the Glowforge’s log files.
The next phase is the homing sequence.
After the Glowforge has connected to the cloud, uploaded its current settings, and told the service it’s ready, the cloud sends down a command to begin the HUNT cycle (this is just a fancy way of saying “Find the focal lens’ home position”):
2018-02-27_23:43:01.04874 10400 INFO: hunt [10152215]: state=ready
Before performing any type of motion, the device checks to see if a firmware update is in progress. If not, it acquires an update lock preventing such updates until it is released:
2018-02-27_23:43:01.06212 10404 DEBUG: updater lock acquired
Once the lock is set, it resets the internal X,Y & Z position counters to 0, and downloads the HUNT motion file from the cloud:
2018-02-27_23:43:01.06217 10405 INFO: hw: clearing pulse data
2018-02-27_23:43:01.06219 10405 INFO: hw: clearing position
2018-02-27_23:43:01.06221 10405 INFO: hunt [10152215]: downloading pulse data from https://storage.googleapis.com/glowforge-files/actions/hunt/hunt-signed-offset--12-step-size-0.35306.puls?GoogleAccessId=production@glowforge-production.iam.gserviceaccount.com&Signature=bNzL%2F%2BIIZHahtcNszP46c6v6gc3%2FPxb4rm3AglHY86DcOGNpl21GhFaFycx1%0AKtXfhJCMFDpYlfkXF484MVWoxpoMA8MbpNNwcFUoX%2FDBANmI710DJ2Wm3Hi9%0Ar%2BuN%2BbjHQNFSioKQfyZDkeN0dS070MuU4NCMgaaatJ3ddd8MhQSEACxhBchc%0AqTdaK6K5QWaEhEAjIZdpNeetR7lSzSPOoRNtnt5goDBj%2FGBhiC1rZiUeNmEC%0AmanUwtuKAtPrWzahfXpyH%2B5ml2q6KSm3kcIEEcEUB86IdZZYXjHzzs3x3LHB%0A45UsF3pP1qG3cItP2SE1gO9kebCECnIo3RvGIFQ1eQ%3D%3D&Expires=1519776180
The download links for motion files have a very short life, so don’t bother trying to download it - it is well past its expiration date. (If you must have one for your collection, you’ll find samples of them here.)
The hunt motion file is special. It contains is a predetermined number of steps for moving the lens after its factory determined “reference” position is established. The exact number of these steps will vary by machine, as does the reference position. The device in these log files requires 12 steps. My particular unit requires 8. Check your log files and comment below to tell us your lens homing number! 
Before we actually use this magic file, we have to get the lens to its reference position. The process makes use of a magnet on the lens carrier, and a sensor in the housing:
The lens carrier is the white plastic part, the magnet is in the red circle, and the sensor sits in the groove seen below the magnet in the picture.
To home the lens, the carrier is moved all the way up until the magnet trips the sensor (assertion). Then it is moved down until the magnet is no longer detected (deassertion). This process is repeated (5 or 6 times), and the results compared:
2018-02-27_23:43:01.52954 10875 INFO: Z axis homing started, step interval is 180 ms
2018-02-27_23:43:01.70418 11056 DEBUG: z_mode_enable: setting to 0
2018-02-27_23:43:01.74721 11057 INFO: Z axis: set full step mode
2018-02-27_23:43:01.74724 11058 DEBUG: air_assist_pwm: setting to 204
2018-02-27_23:43:01.74725 11062 DEBUG: air_assist_data_logging_interval: setting to 1000 ms
2018-02-27_23:43:01.74725 11062 DEBUG: z_stepper_current: setting to 0
2018-02-27_23:43:01.74726 11066 DEBUG: beam_detect_irq: setting to 1
2018-02-27_23:43:01.74727 11067 INFO: Z axis homing started; seeking toward bed until sensor de-assertion
2018-02-27_23:43:01.88574 11237 INFO: Pass 1: Z home deassertion after 0 half steps toward bed; set as reference position
2018-02-27_23:43:01.89339 11238 INFO: Z axis seeking away from bed until sensor assertion
2018-02-27_23:43:03.33606 12688 INFO: Pass 1: Z home assertion at 14 half steps from reference position
2018-02-27_23:43:04.06233 13414 INFO: Pass 2: Z home deassertion at 8 half steps from reference position
2018-02-27_23:43:04.96568 13417 INFO: Z axis seeking away from bed until sensor assertion
2018-02-27_23:43:04.96573 14137 INFO: Pass 2: Z home assertion at 14 half steps from reference position
2018-02-27_23:43:05.51255 14864 INFO: Pass 3: Z home deassertion at 8 half steps from reference position
2018-02-27_23:43:05.51259 14864 INFO: Z axis seeking away from bed until sensor assertion
2018-02-27_23:43:06.23505 15586 INFO: Pass 3: Z home assertion at 14 half steps from reference position
2018-02-27_23:43:06.96006 16312 INFO: Pass 4: Z home deassertion at 8 half steps from reference position
2018-02-27_23:43:07.06080 16313 INFO: Z axis seeking away from bed until sensor assertion
2018-02-27_23:43:07.68630 17035 INFO: Pass 4: Z home assertion at 14 half steps from reference position
2018-02-27_23:43:08.41004 17761 INFO: Pass 5: Z home deassertion at 8 half steps from reference position
2018-02-27_23:43:08.41009 17762 INFO: Z axis seeking away from bed until sensor assertion
2018-02-27_23:43:09.13665 18486 INFO: Pass 5: Z home assertion at 14 half steps from reference position
2018-02-27_23:43:09.14408 18490 INFO: Z homing done after 5 passes with 100.0% agreement (at 14)
2018-02-27_23:43:09.31478 18666 INFO: Z axis homing finished
2018-02-27_23:43:09.31483 18666 DEBUG: z_mode_enable: setting to 1
2018-02-27_23:43:09.82859 18672 INFO: Z axis: set half step mode
This establishes a solid reference position. To get the lens to the proper height for a known focal position, the previously downloaded hunt motion file (with the factory determined number of steps) is executed:
2018-02-27_23:43:09.89135 18776 DEBUG: HWFSM: event ENTRY handled by state running
...
2018-02-27_23:43:09.90850 18783 DEBUG: hw: driver state is now 'running', progress=456/18172, pos=(0,0,-1)
2018-02-27_23:43:09.90852 18783 DEBUG: hw: switch event #0/2 value 0 code 4
2018-02-27_23:43:09.90853 18783 INFO: ESTOP deactivated
2018-02-27_23:43:11.20462 20556 DEBUG: hw: driver state is now 'idle', progress=18172/18172, pos=(0,0,-12)
2018-02-27_23:43:11.21863 20558 DEBUG: HWFSM: event CNC_STOPPED handled by state running
2018-02-27_23:43:11.21868 20558 DEBUG: HWFSM: event EXIT handled by state running
2018-02-27_23:43:11.21869 20558 DEBUG: HWFSM: running => finished
You can see that at the end of the run, the lens (the Z axis) is now at the -12 step position, and is happily at home. Where exactly is this home position? I believe it is the 0.000 focal height (or maybe even 0.010"), but I haven’t confirmed that. Someone up for the challenge?
It’s now time for the first lid image…
2018-02-27_23:43:12.44328 21794 INFO: lid_image [10152238]: state=ready
2018-02-27_23:43:12.45417 21796 DEBUG: setting CAM_AUTO_EXPOSURE=0
2018-02-27_23:43:12.45422 21798 DEBUG: setting CAM_EXPOSURE=3000
2018-02-27_23:43:12.45423 21800 DEBUG: setting CAM_AUTO_GAIN=0
2018-02-27_23:43:12.45424 21801 DEBUG: setting CAM_GAIN=30
2018-02-27_23:43:12.46245 21810 DEBUG: setting CAM_AUTO_WHITE_BALANCE=2
2018-02-27_23:43:12.46250 21811 DEBUG: setting CAM_RED_BALANCE=1100
2018-02-27_23:43:12.48967 21815 DEBUG: setting CAM_BLUE_BALANCE=1400
2018-02-27_23:43:12.48970 21817 DEBUG: setting CAM_FLASH_MODE=2
2018-02-27_23:43:12.48971 21818 DEBUG: setting CAM_FLASH_ON=0
2018-02-27_23:43:12.48971 21819 DEBUG: setting CAM_HFLIP=1
2018-02-27_23:43:12.48972 21820 DEBUG: setting CAM_VFLIP=0
2018-02-27_23:43:12.48973 21822 INFO: cam: capturing lid image
2018-02-27_23:43:12.48973 21823 DEBUG: cam: Setting head illumination to 0
2018-02-27_23:43:12.48974 21823 DEBUG: white_led: setting to 0
2018-02-27_23:43:12.48975 21825 DEBUG: uv_led: setting to 0
2018-02-27_23:43:12.48975 21826 DEBUG: mhs_laser: setting to 0
2018-02-27_23:43:12.48976 21827 INFO: cam: flushing pipeline
2018-02-27_23:43:12.62721 21979 INFO: cam: camera is in use
2018-02-27_23:43:12.66171 21980 DEBUG: setting CAM_STANDBY=0
2018-02-27_23:43:12.66174 21981 INFO: cam: waiting for a frame...
2018-02-27_23:43:12.74384
2018-02-27_23:43:12.74389 (glowforge:620): GStreamer-WARNING **: /bamboo/xml-data/build-dir/FIR-MAS11-BIM/poky/build/tmp/work/cortexa9hf-vfp-neon-poky-linux-gnueabi/gstreamer1.0/1.4.5-r0/gstreamer-1.4.5/gst/gstpad.c:4655:store_sticky_event:<outputselector0:src_0> Sticky event misordering, got 'segment' before 'stream-start'
2018-02-27_23:43:12.74391
2018-02-27_23:43:12.74392 (glowforge:620): GStreamer-WARNING **: /bamboo/xml-data/build-dir/FIR-MAS11-BIM/poky/build/tmp/work/cortexa9hf-vfp-neon-poky-linux-gnueabi/gstreamer1.0/1.4.5-r0/gstreamer-1.4.5/gst/gstpad.c:4655:store_sticky_event:<bayer2rgb0:src> Sticky event misordering, got 'segment' before 'stream-start'
2018-02-27_23:43:12.74393
2018-02-27_23:43:12.74395 (glowforge:620): GStreamer-WARNING **: /bamboo/xml-data/build-dir/FIR-MAS11-BIM/poky/build/tmp/work/cortexa9hf-vfp-neon-poky-linux-gnueabi/gstreamer1.0/1.4.5-r0/gstreamer-1.4.5/gst/gstpad.c:4655:store_sticky_event:<jpegenc0:sink> Sticky event misordering, got 'segment' before 'stream-start'
2018-02-27_23:43:12.74396
2018-02-27_23:43:12.76020 (glowforge:620): GStreamer-WARNING **: /bamboo/xml-data/build-dir/FIR-MAS11-BIM/poky/build/tmp/work/cortexa9hf-vfp-neon-poky-linux-gnueabi/gstreamer1.0/1.4.5-r0/gstreamer-1.4.5/gst/gstpad.c:4655:store_sticky_event:<bayer2rgb0:sink> Sticky event misordering, got 'segment' before 'stream-start'
2018-02-27_23:43:12.76025
2018-02-27_23:43:12.76027 (glowforge:620): GStreamer-WARNING **: /bamboo/xml-data/build-dir/FIR-MAS11-BIM/poky/build/tmp/work/cortexa9hf-vfp-neon-poky-linux-gnueabi/gstreamer1.0/1.4.5-r0/gstreamer-1.4.5/gst/gstpad.c:4655:store_sticky_event:<outputselector0:src_0> Sticky event misordering, got 'segment' before 'caps'
2018-02-27_23:43:12.76028
2018-02-27_23:43:12.76030 (glowforge:620): GStreamer-WARNING **: /bamboo/xml-data/build-dir/FIR-MAS11-BIM/poky/build/tmp/work/cortexa9hf-vfp-neon-poky-linux-gnueabi/gstreamer1.0/1.4.5-r0/gstreamer-1.4.5/gst/gstpad.c:4655:store_sticky_event:<bayer2rgb0:src> Sticky event misordering, got 'segment' before 'caps'
2018-02-27_23:43:12.76031
2018-02-27_23:43:12.78942 (glowforge:620): GStreamer-WARNING **: /bamboo/xml-data/build-dir/FIR-MAS11-BIM/poky/build/tmp/work/cortexa9hf-vfp-neon-poky-linux-gnueabi/gstreamer1.0/1.4.5-r0/gstreamer-1.4.5/gst/gstpad.c:4655:store_sticky_event:<jpegenc0:sink> Sticky event misordering, got 'segment' before 'caps'
2018-02-27_23:43:12.78945
2018-02-27_23:43:12.78946 (glowforge:620): GStreamer-WARNING **: /bamboo/xml-data/build-dir/FIR-MAS11-BIM/poky/build/tmp/work/cortexa9hf-vfp-neon-poky-linux-gnueabi/gstreamer1.0/1.4.5-r0/gstreamer-1.4.5/gst/gstpad.c:4655:store_sticky_event:<bayer2rgb0:sink> Sticky event misordering, got 'segment' before 'caps'
2018-02-27_23:43:13.43974 22791 DEBUG: hw: switch event #0/2 value 1 code 2
2018-02-27_23:43:13.43976 22791 INFO: button pressed
2018-02-27_23:43:14.05387 23405 INFO: cam: received a frame
2018-02-27_23:43:14.05389 23405 DEBUG: cam: Turning all camera illumination off
2018-02-27_23:43:14.05390 23406 DEBUG: setting CAM_FLASH_ON=0
2018-02-27_23:43:14.68768 23409 DEBUG: white_led: setting to 0
2018-02-27_23:43:14.68773 23410 DEBUG: uv_led: setting to 0
2018-02-27_23:43:14.68775 23412 DEBUG: mhs_laser: setting to 0
2018-02-27_23:43:14.68776 23413 INFO: cam: camera is not in use
2018-02-27_23:43:14.68777 23413 DEBUG: cam: currentCameraCaptureHandler setting head illumination=0
2018-02-27_23:43:14.68779 23413 INFO: lid_image [10152238]: capture time: 1.61799
2018-02-27_23:43:14.68780 23414 INFO: uploading 559708 bytes to https://app.glowforge.com/api/machines/lid_image/10152238
2018-02-27_23:43:14.68781 23793 INFO: 1000 ms
2018-02-27_23:43:15.42322 24775 INFO: image upload: url=https://app.glowforge.com/api/machines/lid_image/10152238 http_code=200, result=0 (OK)
As you can see, after it snaps the picture, it uploads it to the cloud and lets the service know that task is complete.
At this point, somewhere in the cloud, a highly trained intelligence is hard at work determining the exact location of your Glowforge’s head. The trained squirrel scene from Johnny Depp’s version of Willie Wonka comes to mind… When that is complete, a freshly computed motion is presented to the Glowforge to send the head repeatedly crashing into the side (the squirrels supposedly received more training and this problem is reportedly fixed):
2018-02-27_23:43:22.73088 32082 INFO: motion [10152263]: state=ready
2018-02-27_23:43:22.74385 32087 DEBUG: updater lock acquired
2018-02-27_23:43:22.74390 32087 INFO: hw: clearing pulse data
2018-02-27_23:43:22.74391 32087 INFO: hw: clearing position
2018-02-27_23:43:22.74393 32087 INFO: motion [10152263]: downloading pulse data from https://storage.googleapis.com/glowforge-files/motion/1519093694-nooptions-aeaf92f37053e2f18f55c7ee161958bffb5f057f.puls?GoogleAccessId=production@glowforge-production.iam.gserviceaccount.com&Signature=ZdoAUABSjCgzQk9FAeh1Ca3REx8QdF5OG6tzt3Pk5mRQu%2FFfaT%2BcBgHVsdmP%0AUeT%2BlX7hV1EkibDCX1OxGzxtRR4B%2BPBj%2BaSHn5xzJrD9GnX19XBClyRZgiJS%0ACKtaAaepa0KZgaVDquWo242tT0cV%2BZwh%2BmcThafo59nmi0i9NQGRXXcoohkW%0Ado7WaBnjg2TmfIdf6L6NqKkEUoY%2BkkBLOE%2B6rw8hH6Nw%2Bu0VkGmmUm5Sroym%0A06I0czb6KILP6nUZefkrutL0L2dIrovK9P0VMcQ4k68ItU%2BHMMEPtNQOnBJ7%0AofA8Qo5w27zvBu%2BnyHNbZAmasDvlIgB0YHI%2B%2B4KiZw%3D%3D&Expires=1519776202
...
2018-02-27_23:43:23.12967 32478 DEBUG: hw: driver state is now 'running', progress=367/43071, pos=(3,1,0)
2018-02-27_23:43:23.12968 32478 DEBUG: hw: switch event #0/2 value 0 code 4
2018-02-27_23:43:23.12969 32478 INFO: ESTOP deactivated
2018-02-27_23:43:23.45612 32807 INFO: 10000 ms
2018-02-27_23:43:23.45616 32808 INFO: hw: button held long
2018-02-27_23:43:26.30989 35661 DEBUG: hw: switch event #0/2 value 0 code 2
2018-02-27_23:43:26.30994 35661 INFO: button released
2018-02-27_23:43:27.39871 36749 DEBUG: hw: driver state is now 'idle', progress=43071/43071, pos=(13093,7402,0)
2018-02-27_23:43:27.40324 36749 DEBUG: HWFSM: event CNC_STOPPED handled by state running
2018-02-27_23:43:27.40326 36749 DEBUG: HWFSM: event EXIT handled by state running
2018-02-27_23:43:27.40327 36749 DEBUG: HWFSM: running => finished
After this is done, another lid image is commanded, and the process repeats until homing is complete.
In the case of this log file, though, the process was interrupted by the user holding down the button for a long enough period to trigger WiFi setup mode.
An interesting (maybe) side note: The number inside the brackets that accompanies the commands from the cloud (motion [10152263]) is an incremental counter that appears to increase by 1 for each command the cloud sends out to any connected client. If one were interested in determining an estimate of server load at any given time, one could look at their log files and plot the count increments over periods of time. Just a thought.
Next time, we’ll look at logs resulting from a successful “print”.