Interpreting Log Files: 2 - Homing Sequence


#1

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! :wink:

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”.


#2

I also believe the lens homes to 0, i.e. focus at the bed because it steps a distance equal to the specified focus of the first operation at the start of the motion file.