DSF 1.3.1 (unstable) released

chrishamm

I'm happy to announce the release of DSF 1.3.1 for testers. It is now available on the unstable Duet3D package feed. For a list of changes, see https://github.com/chrishamm/DuetSoftwareFramework/releases/tag/1.3.1

If you want to give it a try, have a look at this article. Again, please be aware that this build contains lots of changes since DSF 1.2.4 and some things may not work as expected. That being said, here some notes:

If you see messages like "DCS is shutting down" or "DCS is stopped" this means that DuetControlServer, the main application doing G-code coordination and file management, is no longer running. To figure out why it isn't, connect to your Raspberry Pi using SSH or open a terminal and run sudo journalctl -u duetcontrolserver -en 100 --no-pager and post the output here
If some parts of the web interface do not seem to be regularly updated, it indicates that there is an incompatibility between RRF's and DSF's internal object model. Likewise, connect to your board or open a terminal, run sudo journalctl -u duetcontrolserver -f and look for error messages
If this does not reveal any error messages or if anything gets stuck, please open a terminal and send sudo systemctl stop duetcontrolserver followed by sudo /opt/dsf/bin/DuetControlServer -l debug. This will generate extra debug messages that may show what is going on. Please note that you must not close the terminal as long as you are printing, else the print job will fail.

If you get any error messages, please share them here and I will fix them in the next build.

gtj0

It looks like the model updates for temperature are a little "different".
I'm seeing repeated updates for the same temperature. It's almost as though the temp is changing but it's the same value being reported. Then every once in a while, the value will actually change.

gtj0

I think print time isn't being parsed any more. Filament is OK though.

; Build Summary
;   Build time: 1 hour 46 minutes
;   Filament length: 17057.0 mm (17.06 m)
;   Plastic volume: 41026.81 mm^3 (41.03 cc)
;   Plastic weight: 51.28 g (0.11 lb)
;   Material cost: 2.36

"job" : {
         "build" : {
            "currentObject" : -1,
            "m486Names" : false,
            "m486Numbers" : false,
            "objects" : []
         },
         "duration" : 2162.3,
         "file" : {
            "filament" : [
               17057
            ],
            "fileName" : "0:/gcodes//Center Plate.gcode",
            "firstLayerHeight" : 0.2,
            "generatedBy" : "Simplify3D(R) Version 4.1.1",
            "height" : 13.4,
            "lastModified" : "2020-04-04T09:15:35",
            "layerHeight" : 0.2,
            "numLayers" : 67,
            "printTime" : null,
            "simulatedTime" : null,
            "size" : 6411527
         },
         "filePosition" : 1681672,
         "firstLayerDuration" : 448.59402,
         "lastFileAborted" : false,
         "lastFileCancelled" : true,
         "lastFileName" : "0:/gcodes//Center Plate.gcode",
         "lastFileSimulated" : false,
         "layer" : 12,
         "layerTime" : 56.9,
         "layers" : [],
         "timesLeft" : {
            "filament" : 4446,
            "file" : 4724,
            "layer" : 7623
         },
         "warmUpDuration" : 0
      }

dc42

@gtj0 said in DSF 1.3.1 (unstable) released:

It looks like the model updates for temperature are a little "different".
I'm seeing repeated updates for the same temperature. It's almost as though the temp is changing but it's the same value being reported. Then every once in a while, the value will actually change.

Model variables marked "live" in the object model are reported by RRF to DSF continuously. This includes temperatures, axis coordinates, current/requested speed, voltages and several other variables. That's probably what you are seeing.

gtj0

@dc42 Hmmm. I think what's throwing me off is that sometimes objects are there with changing values, sometimes there without values, sometimes not there at all, and sometimes there with static values.

In this example, "boards" is only there if the vIn has changed but "fans" is always there with empty values. "tools" is always there with the active and standby temps even though they never change.

{
  "boards": [
    {
      "vIn": {
        "current": 25.3
      }
    }
  ],
  "fans": [
    {},
    {},
    {},
    null,
    null,
    null,
    null,
    null,
    null,
    null,
    {},
    {}
  ],
  "inputs": [
    {},
    {},
    {
      "lineNumber": 130116,
      "state": "waiting"
    },
    {},
    {},
    {},
    {},
    {},
    {},
    {},
    {}
  ],
  "job": {
    "duration": 4029.3,
    "filePosition": 3535962,
    "layerTime": 4.1
  },
  "move": {
    "axes": [
      {
        "userPosition": 49.28
      },
      {
        "machinePosition": -24.88,
        "userPosition": 49.28
      },
      {}
    ],
    "extruders": [
      {
        "position": 10425.8
      }
    ]
  },
  "sensors": {
    "probes": [
      {
        "value": [
          553
        ]
      }
    ]
  },
  "tools": [
    {
      "active": [
        225
      ],
      "standby": [
        160
      ]
    }
  ]
}

dc42

@gtj0 said in DSF 1.3.1 (unstable) released:

In this example, "boards" is only there if the vIn has changed but "fans" is always there with empty values. "tools" is always there with the active and standby temps even though they never change.

Yes, that's because the fan RPMs and tool temperatures are flagged as live in the OM - although I thought the vin fields of boards was live too.

gtj0

@dc42 I'm not quite following. Fan RPMs are marked as live but they're not showing. In my case, they're zero anyway since I don't have the tach inputs connected but shouldn't they still show as zero? What about fan speeds? Are they live? The tool active and standby temps are considered live so they always show but the actual heater temps which should also be considered live don't show unless changed. It's very confusing.

I think we need to hear from @chrishamm on what "live" means to the DSF.

gruen

nothing works, power cycle doesn't help:

Duet Control Server v1.3.1
Written by Christian Hammacher for Duet3D
Licensed under the terms of the GNU Public License Version 3

[info] Settings loaded
[info] Environment initialized
[warn] Bad data checksum (expected 0xa23d, got 0x5ef8)
[warn] Bad data checksum (expected 0xa23d, got 0x5ef8)
[warn] Bad data checksum (expected 0xa23d, got 0x5ef8)
[warn] Restarting transfer because the number of maximum retries has been exceeded
[error] Duet is not available

gtj0

@gruen I have to ask... was it working before and with which version?

Can you paste the contents of /opt/dsf/conf/config.json.
Can you change the "LogLevel" entry to "debug" and restart the DCS and paste the output.

gruen

@gtj0

here is the config.json

{
  "LogLevel": "info",
  "SocketDirectory": "/var/run/dsf",
  "SocketFile": "dcs.sock",
  "Backlog": 4,
  "SocketPollInterval": 2000,
  "BaseDirectory": "/opt/dsf/sd",
  "HostUpdateInterval": 4000,
  "MaxMessageAge": 60,
  "SpiDevice": "/dev/spidev0.0",
  "SpiFrequency": 8000000,
  "SpiTransferTimeout": 500,
  "MaxSpiRetries": 3,
  "SpiPollDelay": 25,
  "SpiPollDelaySimulating": 5,
  "GpioChipDevice": "/dev/gpiochip0",
  "TransferReadyPin": 25,
  "BufferedPrintCodes": 32,
  "BufferedMacroCodes": 16,
  "MaxBufferSpacePerChannel": 1536,
  "ModelUpdateInterval": 250,
  "MaxMachineModelLockTime": -1,
  "FileInfoReadBufferSize": 8192,
  "FileInfoReadLimitHeader": 12288,
  "FileInfoReadLimitFooter": 262144,
  "MaxLayerHeight": 0.9,
     
}

removed: "LayerHeightFilters"

-- Logs begin at Sat 2020-04-04 22:30:02 CEST, end at Sat 2020-04-04 22:30:59 CEST. --
Apr 04 22:30:05 Duet6 systemd[1]: Started Duet Control Server.
Apr 04 22:30:09 Duet6 DuetControlServer[335]: Duet Control Server v1.3.1
Apr 04 22:30:09 Duet6 DuetControlServer[335]: Written by Christian Hammacher for Duet3D
Apr 04 22:30:09 Duet6 DuetControlServer[335]: Licensed under the terms of the GNU Public License Version 3
Apr 04 22:30:12 Duet6 DuetControlServer[335]: [info] Settings loaded
Apr 04 22:30:12 Duet6 DuetControlServer[335]: [info] Environment initialized
Apr 04 22:30:12 Duet6 DuetControlServer[335]: [warn] Bad data checksum (expected 0x31c7, got 0xe55f)
Apr 04 22:30:12 Duet6 DuetControlServer[335]: [warn] Bad data checksum (expected 0x31c7, got 0xe55f)
Apr 04 22:30:12 Duet6 DuetControlServer[335]: [warn] Bad data checksum (expected 0x31c7, got 0xe55f)
Apr 04 22:30:12 Duet6 DuetControlServer[335]: [warn] Restarting transfer because the number of maximum retries has been exceeded
Apr 04 22:30:12 Duet6 DuetControlServer[335]: [error] Duet is not available
Apr 04 22:30:12 Duet6 systemd[1]: duetcontrolserver.service: Succeeded.
Apr 04 22:30:17 Duet6 systemd[1]: duetcontrolserver.service: Service RestartSec=5s expired, scheduling restart.
Apr 04 22:30:17 Duet6 systemd[1]: duetcontrolserver.service: Scheduled restart job, restart counter is at 1.
Apr 04 22:30:17 Duet6 systemd[1]: Stopped Duet Control Server.
Apr 04 22:30:17 Duet6 systemd[1]: Started Duet Control Server.
Apr 04 22:30:18 Duet6 DuetControlServer[737]: Duet Control Server v1.3.1
Apr 04 22:30:18 Duet6 DuetControlServer[737]: Written by Christian Hammacher for Duet3D
Apr 04 22:30:18 Duet6 DuetControlServer[737]: Licensed under the terms of the GNU Public License Version 3
Apr 04 22:30:19 Duet6 DuetControlServer[737]: [info] Settings loaded
Apr 04 22:30:19 Duet6 DuetControlServer[737]: [info] Environment initialized
Apr 04 22:30:19 Duet6 DuetControlServer[737]: [warn] Bad data checksum (expected 0x31c7, got 0xe55f)
Apr 04 22:30:19 Duet6 DuetControlServer[737]: [warn] Bad data checksum (expected 0x31c7, got 0xe55f)
Apr 04 22:30:19 Duet6 DuetControlServer[737]: [warn] Bad data checksum (expected 0x31c7, got 0xe55f)
Apr 04 22:30:19 Duet6 DuetControlServer[737]: [warn] Restarting transfer because the number of maximum retries has been exceeded
Apr 04 22:30:19 Duet6 DuetControlServer[737]: [error] Duet is not available
Apr 04 22:30:19 Duet6 systemd[1]: duetcontrolserver.service: Succeeded.
Apr 04 22:30:25 Duet6 systemd[1]: duetcontrolserver.service: Service RestartSec=5s expired, scheduling restart.
Apr 04 22:30:25 Duet6 systemd[1]: duetcontrolserver.service: Scheduled restart job, restart counter is at 2.
Apr 04 22:30:25 Duet6 systemd[1]: Stopped Duet Control Server.
Apr 04 22:30:25 Duet6 systemd[1]: Started Duet Control Server.
Apr 04 22:30:25 Duet6 DuetControlServer[1054]: Duet Control Server v1.3.1
Apr 04 22:30:25 Duet6 DuetControlServer[1054]: Written by Christian Hammacher for Duet3D
Apr 04 22:30:25 Duet6 DuetControlServer[1054]: Licensed under the terms of the GNU Public License Version 3
Apr 04 22:30:26 Duet6 DuetControlServer[1054]: [info] Settings loaded
Apr 04 22:30:27 Duet6 DuetControlServer[1054]: [info] Environment initialized
Apr 04 22:30:27 Duet6 DuetControlServer[1054]: [warn] Bad data checksum (expected 0x31c7, got 0xe55f)
Apr 04 22:30:27 Duet6 DuetControlServer[1054]: [warn] Bad data checksum (expected 0x31c7, got 0xe55f)
Apr 04 22:30:27 Duet6 DuetControlServer[1054]: [warn] Bad data checksum (expected 0x31c7, got 0xe55f)
Apr 04 22:30:27 Duet6 DuetControlServer[1054]: [warn] Restarting transfer because the number of maximum retries has been exceeded
Apr 04 22:30:27 Duet6 DuetControlServer[1054]: [error] Duet is not available
Apr 04 22:30:27 Duet6 systemd[1]: duetcontrolserver.service: Succeeded.
Apr 04 22:30:32 Duet6 systemd[1]: duetcontrolserver.service: Service RestartSec=5s expired, scheduling restart.
Apr 04 22:30:32 Duet6 systemd[1]: duetcontrolserver.service: Scheduled restart job, restart counter is at 3.
Apr 04 22:30:32 Duet6 systemd[1]: Stopped Duet Control Server.
Apr 04 22:30:32 Duet6 systemd[1]: Started Duet Control Server.
Apr 04 22:30:32 Duet6 DuetControlServer[1227]: Duet Control Server v1.3.1
Apr 04 22:30:32 Duet6 DuetControlServer[1227]: Written by Christian Hammacher for Duet3D
Apr 04 22:30:32 Duet6 DuetControlServer[1227]: Licensed under the terms of the GNU Public License Version 3
Apr 04 22:30:34 Duet6 DuetControlServer[1227]: [info] Settings loaded
Apr 04 22:30:34 Duet6 DuetControlServer[1227]: [info] Environment initialized
Apr 04 22:30:34 Duet6 DuetControlServer[1227]: [warn] Bad data checksum (expected 0x31c7, got 0xe55f)
Apr 04 22:30:34 Duet6 DuetControlServer[1227]: [warn] Bad data checksum (expected 0x31c7, got 0xe55f)
Apr 04 22:30:34 Duet6 DuetControlServer[1227]: [warn] Bad data checksum (expected 0x31c7, got 0xe55f)
Apr 04 22:30:34 Duet6 DuetControlServer[1227]: [warn] Restarting transfer because the number of maximum retries has been exceeded
Apr 04 22:30:34 Duet6 DuetControlServer[1227]: [error] Duet is not available
Apr 04 22:30:34 Duet6 systemd[1]: duetcontrolserver.service: Succeeded.
Apr 04 22:30:52 Duet6 systemd[1]: duetcontrolserver.service: Service RestartSec=5s expired, scheduling restart.
Apr 04 22:30:52 Duet6 systemd[1]: duetcontrolserver.service: Scheduled restart job, restart counter is at 4.
Apr 04 22:30:52 Duet6 systemd[1]: Stopped Duet Control Server.
Apr 04 22:30:52 Duet6 systemd[1]: Started Duet Control Server.
Apr 04 22:30:53 Duet6 DuetControlServer[1241]: Duet Control Server v1.3.1
Apr 04 22:30:53 Duet6 DuetControlServer[1241]: Written by Christian Hammacher for Duet3D
Apr 04 22:30:53 Duet6 DuetControlServer[1241]: Licensed under the terms of the GNU Public License Version 3
Apr 04 22:30:54 Duet6 DuetControlServer[1241]: [info] Settings loaded
Apr 04 22:30:55 Duet6 DuetControlServer[1241]: [info] Environment initialized
Apr 04 22:30:55 Duet6 DuetControlServer[1241]: [warn] Bad data checksum (expected 0x31c7, got 0xe55f)
Apr 04 22:30:55 Duet6 DuetControlServer[1241]: [warn] Bad data checksum (expected 0x31c7, got 0xe55f)
Apr 04 22:30:55 Duet6 DuetControlServer[1241]: [warn] Bad data checksum (expected 0x31c7, got 0xe55f)
Apr 04 22:30:55 Duet6 DuetControlServer[1241]: [warn] Restarting transfer because the number of maximum retries has been exceeded
Apr 04 22:30:55 Duet6 DuetControlServer[1241]: [error] Duet is not available
Apr 04 22:30:55 Duet6 systemd[1]: duetcontrolserver.service: Succeeded.

gruen

RC5 works for me, how can I downgrade?

wilriker

@gruen Have your tried reflashing the Duet? I've seen this before sometimes and strangely (coincidentally?) it only went away after flashing the firmware again.

tobias_munich

@chrishamm @dc42 thank you guys,

after updating via apt upgrade the system is running again.
a new test print is running.

Update: After 1h of printing DCS lost the connection again

gtj0

The default SpiFrequency in /opt/dsf/conf/config.json changed from 2000000 (2MHz) to 8000000 (8MHz) with the recent release. Try changing it back to 2000000 and see what happens. Experiment to see what the fastest speed you can reliably run at.

chrishamm

@tobias_munich Sorry to hear you are having problems. Can you check for error messages when DCS disconnected? Can you share the output of M122?

@gruen Please do what @gtj0 said.

gtj0

@chrishamm Do you want me to open github issues for the print time and model issues I mentioned above?

mikedahlgren

@chrishamm Shared elsewhere but here is the results of "sudo journalctl -u duetcontrolserver -en 100 --no-pager"

Apr 06 18:02:00 duet3 DuetControlServer[13291]: Duet Control Server v1.3.1
Apr 06 18:02:00 duet3 DuetControlServer[13291]: Written by Christian Hammacher for Duet3D
Apr 06 18:02:00 duet3 DuetControlServer[13291]: Licensed under the terms of the GNU Public License Version 3
Apr 06 18:02:01 duet3 DuetControlServer[13291]: [info] Settings loaded
Apr 06 18:02:01 duet3 DuetControlServer[13291]: [info] Environment initialized
Apr 06 18:02:01 duet3 DuetControlServer[13291]: [warn] RepRapFirmware got a bad header checksum
Apr 06 18:02:01 duet3 DuetControlServer[13291]: [info] Connection to Duet established
Apr 06 18:02:01 duet3 DuetControlServer[13291]: [info] IPC socket created at /var/run/dsf/dcs.sock
Apr 06 18:02:01 duet3 DuetControlServer[13291]: [info] Aux: Running code from firmware 'M20 S2 P0:/macros' on channel Aux
Apr 06 18:02:02 duet3 DuetControlServer[13291]: [fatal] Abnormal program termination
Apr 06 18:02:02 duet3 DuetControlServer[13291]: [fatal] Update task faulted
Apr 06 18:02:02 duet3 DuetControlServer[13291]: System.ArgumentException: Requested value 'fault' was not found.
Apr 06 18:02:02 duet3 DuetControlServer[13291]: at System.Enum.TryParseByName(RuntimeType enumType, String originalValueString, ReadOnlySpan1 value, Boolean ignoreCase, Boolean throwOnFailure, UInt64& result) Apr 06 18:02:02 duet3 DuetControlServer[13291]: at System.Enum.TryParseInt32Enum(RuntimeType enumType, String originalValueString, ReadOnlySpan1 value, Int32 minInclusive, Int32 maxInclusive, Boolean ignoreCase, Boolean throwOnFailure, TypeCode type, Int32& result)
Apr 06 18:02:02 duet3 DuetControlServer[13291]: at System.Enum.TryParse(Type enumType, String value, Boolean ignoreCase, Boolean throwOnFailure, Object& result)
Apr 06 18:02:02 duet3 DuetControlServer[13291]: at System.Enum.Parse(Type enumType, String value, Boolean ignoreCase)
Apr 06 18:02:02 duet3 DuetControlServer[13291]: at DuetAPI.Utility.JsonLowerCaseStringEnumConverter.JsonLowerCaseStringEnumConverterInner1.Read(Utf8JsonReader& reader, Type typeToConvert, JsonSerializerOptions options) in /home/christian/duet/DuetSoftwareFramework/src/DuetAPI/Utility/JsonLowerCaseStringEnumConverter.cs:line 62 Apr 06 18:02:02 duet3 DuetControlServer[13291]: at System.Text.Json.JsonPropertyInfoNullable2.OnRead(ReadStack& state, Utf8JsonReader& reader)
Apr 06 18:02:02 duet3 DuetControlServer[13291]: at System.Text.Json.JsonPropertyInfo.Read(JsonTokenType tokenType, ReadStack& state, Utf8JsonReader& reader)
Apr 06 18:02:02 duet3 DuetControlServer[13291]: at System.Text.Json.JsonSerializer.ReadCore(JsonSerializerOptions options, Utf8JsonReader& reader, ReadStack& readStack)
Apr 06 18:02:02 duet3 DuetControlServer[13291]: at System.Text.Json.JsonSerializer.ReadCore(Type returnType, JsonSerializerOptions options, Utf8JsonReader& reader)
Apr 06 18:02:02 duet3 DuetControlServer[13291]: at System.Text.Json.JsonSerializer.Deserialize(String json, Type returnType, JsonSerializerOptions options)
Apr 06 18:02:02 duet3 DuetControlServer[13291]: at DuetAPI.Machine.ModelObject.UpdateFromJson(JsonElement jsonElement, Boolean ignoreSbcProperties) in /home/christian/duet/DuetSoftwareFramework/src/DuetAPI/Machine/Base/ModelObject.cs:line 282
Apr 06 18:02:02 duet3 DuetControlServer[13291]: at DuetAPI.Machine.ModelCollectionHelper.UpdateFromJson(IList list, Type itemType, JsonElement jsonElement, Boolean ignoreSbcProperties) in /home/christian/duet/DuetSoftwareFramework/src/DuetAPI/Machine/Base/ModelCollection.cs:line 227
Apr 06 18:02:02 duet3 DuetControlServer[13291]: at DuetAPI.Machine.ModelObject.UpdateFromJson(JsonElement jsonElement, Boolean ignoreSbcProperties) in /home/christian/duet/DuetSoftwareFramework/src/DuetAPI/Machine/Base/ModelObject.cs:line 264
Apr 06 18:02:02 duet3 DuetControlServer[13291]: at DuetAPI.Machine.ModelObject.UpdateFromJson(JsonElement jsonElement, Boolean ignoreSbcProperties) in /home/christian/duet/DuetSoftwareFramework/src/DuetAPI/Machine/Base/ModelObject.cs:line 248
Apr 06 18:02:02 duet3 DuetControlServer[13291]: at DuetAPI.Machine.MachineModel.UpdateFromFirmwareModel(String key, JsonElement jsonElement) in /home/christian/duet/DuetSoftwareFramework/src/DuetAPI/Machine/MachineModel.cs:line 134
Apr 06 18:02:02 duet3 DuetControlServer[13291]: at DuetControlServer.Model.Updater.Run() in /home/christian/duet/DuetSoftwareFramework/src/DuetControlServer/Model/Updater.cs:line 140
Apr 06 18:02:02 duet3 DuetControlServer[13291]: [fatal] Update task faulted

chrishamm

@mikedahlgren Thanks, I've got a fix ready and will release it later this week. Until then the only way to get DCS back working is to reset the Duet 3 using the push button and to wait a moment.

@gtj0 You're right about the printing time and Simplify3D, I'm looking into it. As for the diffs it's all looking good and appears like what DWC would expect, but it's odd that you are seeing the tool temperatures being transmitted over and over again even though nothing has changed. I just tried to reproduce it and I could do this, so I'll fix it as well. Thanks for letting me know!

PS: It's actually Simplify3D that tried to be smart, they're now printing hour instead of hours so my regex doesn't work any more. I'll update it.

mikedahlgren

@chrishamm Thanks you!

gtj0

@chrishamm Can you also comment on the other model oddities like the "fans" object showing in an update but with all empty values. It's kinda confusing because some of the things the RRF model considers "live" show up on every update but others which are also "live" don't.