Manual and cronBackup fails with "Illegal instruction" #2309

myrck · 2023-05-07T09:35:37Z

Describe the issue you are experiencing

I have this problem since version 3.69.6.20230407.

A manual backup via the WebGui fails with this message:

ERROR: creating backup returned unexpected error code 132

child process exited abnormally

And via cmd:

/bin/cronBackup.sh 
Illegal instruction (core dumped)

Describe the behavior you expected

That it will provide me the backup for download.

Steps to reproduce the issue

Einstellungen
Systemsteuerung
Sicherheit
Backup erstellen

What is the version this bug report is based on?

3.69.6.20230407

Which base platform are you running?

oci (Open Container Infrastructure)

Which HomeMatic/homematicIP radio module are you using?

HmIP-RFUSB

Anything in the logs that might be useful for us?

11:26:37 homematic local0.info ReGaHss: Info: start web processing, worker thread #0 {"HTTP-Listener"} [spawnNewProcess():httpListener.cpp:208]
May  7 11:26:37 homematic local0.info ReGaHss: Info: recvd 326 bytes by web server #1 [ThreadFunction():httpServer.cpp:795]
May  7 11:26:37 homematic local0.info ReGaHss: Info: IseSession GetSessionId from URL: /tclrega.exe [GetSessionId():iseSession.cpp:185]
May  7 11:26:37 homematic local0.info ReGaHss: Info: http id #1 sends parsed file [ParseFileAndSendWebResponse():httpServer.cpp:2091]
May  7 11:26:38 homematic local0.info ReGaHss: Info: start web processing, worker thread #0 {"HTTP-Listener"} [spawnNewProcess():httpListener.cpp:208]
May  7 11:26:38 homematic local0.info ReGaHss: Info: recvd 764 bytes by web server #1 [ThreadFunction():httpServer.cpp:795]
May  7 11:26:38 homematic local0.info ReGaHss: Info: IseSession GetSessionId from URL: /esp/system.htm?sid=@EpyHtz5uWC@&action=UpdateUI [GetSessionId():iseSession.cpp:185]
May  7 11:26:38 homematic local0.info ReGaHss: Info: http id #1 sends parsed file [ParseFileAndSendWebResponse():httpServer.cpp:2091]
May  7 11:26:38 homematic local0.info ReGaHss: Info: start web processing, worker thread #0 {"HTTP-Listener"} [spawnNewProcess():httpListener.cpp:208]
May  7 11:26:38 homematic local0.info ReGaHss: Info: recvd 100 bytes by web server #1 [ThreadFunction():httpServer.cpp:795]
May  7 11:26:38 homematic local0.info ReGaHss: Info: IseSession GetSessionId from URL: /tclrega.exe [GetSessionId():iseSession.cpp:185]
May  7 11:26:38 homematic local0.info ReGaHss: Info: http id #1 sends parsed file [ParseFileAndSendWebResponse():httpServer.cpp:2091]
May  7 11:26:38 homematic local0.info ReGaHss: Info: start web processing, worker thread #0 {"HTTP-Listener"} [spawnNewProcess():httpListener.cpp:208]
May  7 11:26:38 homematic local0.info ReGaHss: Info: recvd 104 bytes by web server #1 [ThreadFunction():httpServer.cpp:795]
May  7 11:26:38 homematic local0.info ReGaHss: Info: IseSession GetSessionId from URL: /tclrega.exe [GetSessionId():iseSession.cpp:185]
May  7 11:26:38 homematic local0.info ReGaHss: Info: http id #1 sends parsed file [ParseFileAndSendWebResponse():httpServer.cpp:2091]
May  7 11:26:39 homematic local0.info ReGaHss: Info: start web processing, worker thread #0 {"HTTP-Listener"} [spawnNewProcess():httpListener.cpp:208]
May  7 11:26:39 homematic local0.info ReGaHss: Info: recvd 83 bytes by web server #1 [ThreadFunction():httpServer.cpp:795]
May  7 11:26:39 homematic local0.info ReGaHss: Info: IseSession GetSessionId from URL: /tclrega.exe [GetSessionId():iseSession.cpp:185]
May  7 11:26:39 homematic local0.info ReGaHss: Info: open file succeeded, start save [SaveToFile():iseDOMpersist.cpp:265]
May  7 11:26:39 homematic local0.info ReGaHss: Info: start, count=4777 [RemoveUnreferencedObjects():iseDOMobj.cpp:678]
May  7 11:26:39 homematic local0.info ReGaHss: Info: removed 0 unreferenced objects, count=4777 [RemoveUnreferencedObjects():iseDOMobj.cpp:778]
May  7 11:26:40 homematic local0.info ReGaHss: Info: end save [SaveToFile():iseDOMpersist.cpp:271]
May  7 11:26:40 homematic local0.info ReGaHss: Info: end save to file= /etc/config/homematic.regadom.new [SaveToFile():iseDOMpersist.cpp:279]
May  7 11:26:40 homematic local0.info ReGaHss: Info: saved new file. [SaveOM():iseDOM.cpp:2495]
May  7 11:26:40 homematic local0.info ReGaHss: Info: rename file to bak. [SaveOM():iseDOM.cpp:2516]
May  7 11:26:40 homematic local0.info ReGaHss: Info: rename new file to original. [SaveOM():iseDOM.cpp:2522]
May  7 11:26:40 homematic local0.info ReGaHss: Info: http id #1 sends parsed file [ParseFileAndSendWebResponse():httpServer.cpp:2091]
May  7 11:26:41 homematic local0.info ReGaHss: Info: start web processing, worker thread #0 {"HTTP-Listener"} [spawnNewProcess():httpListener.cpp:208]
May  7 11:26:41 homematic local0.info ReGaHss: Info: recvd 764 bytes by web server #1 [ThreadFunction():httpServer.cpp:795]
May  7 11:26:41 homematic local0.info ReGaHss: Info: IseSession GetSessionId from URL: /esp/system.htm?sid=@EpyHtz5uWC@&action=UpdateUI [GetSessionId():iseSession.cpp:185]
May  7 11:26:41 homematic local0.info ReGaHss: Info: http id #1 sends parsed file [ParseFileAndSendWebResponse():httpServer.cpp:2091]
May  7 11:26:46 homematic local0.info ReGaHss: Info: start web processing, worker thread #0 {"HTTP-Listener"} [spawnNewProcess():httpListener.cpp:208]
May  7 11:26:46 homematic local0.info ReGaHss: Info: recvd 125 bytes by web server #1 [ThreadFunction():httpServer.cpp:795]
May  7 11:26:46 homematic local0.info ReGaHss: Info: IseSession GetSessionId from URL: /index.htm [GetSessionId():iseSession.cpp:185]
May  7 11:26:46 homematic local0.debug ReGaHss: Verbose: flag is set to = 1 from Line = 3255 [SetDOMModifiedFlag():iseESPexec.cpp:13551]
May  7 11:26:46 homematic local0.info ReGaHss: Info: http id #1 sends parsed file [ParseFileAndSendWebResponse():httpServer.cpp:2091]
May  7 11:26:50 homematic local0.info ReGaHss: Info: Event="00041D89B5538B:0"."DUTY_CYCLE_LEVEL"=19.000000 [execute():iseXmlRpc.cpp:331]
May  7 11:26:50 homematic local0.debug ReGaHss: Verbose: call on change; id = 1243 [SetLastDPActionTime():iseDOMchn.h:288]
May  7 11:26:50 homematic local0.debug ReGaHss: Verbose: call on change; id = 1242 [SetLastActionTime():iseDOMdev.h:225]
May  7 11:26:50 homematic local0.debug ReGaHss: Verbose: UpdateValue succeeded; val = 19.000000 [execute():iseXmlRpc.cpp:374]
May  7 11:26:50 homematic local0.debug ReGaHss: Verbose: wait max timeout = 240000 [ThreadFunction():iseRTEvent.cpp:69]
May  7 11:26:50 homematic local0.info ReGaHss: Info: Event="00041D89B5538B:0"."CARRIER_SENSE_LEVEL"=0.000000 [execute():iseXmlRpc.cpp:331]
May  7 11:26:50 homematic local0.debug ReGaHss: Verbose: call on change; id = 1243 [SetLastDPActionTime():iseDOMchn.h:288]
May  7 11:26:50 homematic local0.debug ReGaHss: Verbose: call on change; id = 1242 [SetLastActionTime():iseDOMdev.h:225]
May  7 11:26:50 homematic local0.debug ReGaHss: Verbose: UpdateValue succeeded; val = 0.000000 [execute():iseXmlRpc.cpp:374]
May  7 11:26:50 homematic local0.debug ReGaHss: Verbose: wait max timeout = 240000 [ThreadFunction():iseRTEvent.cpp:69]

Additional information

Docker

The text was updated successfully, but these errors were encountered:

jens-maus · 2023-05-08T21:47:04Z

Please tell more about your docker/oci host you are using. Because the message Illegal instructions tells me that this might be a host hardware that might not be 100% compatible here.

myrck · 2023-05-09T07:23:34Z

I use Debian 11 with Docker version 20.10.5+dfsg1, build 55c4c88.
And my docker container:

  homematic:
    image: ghcr.io/jens-maus/raspberrymatic:latest
    container_name: homematic
    hostname: homematic
    privileged: true
    restart: unless-stopped
    stop_grace_period: 30s
    volumes:
      - homematic_data:/usr/local:rw
      - /lib/modules:/lib/modules:ro
      - /run/udev/control:/run/udev/control
    networks:
      mnet_net:
        ipv4_address: 192.168.0.32
      default:

Today I tried a rollback to image 3.67.10.20230225 and the backup worked again. When I switch back to 3.69.6.20230407 or the lastest, backups no longer works.

jens-maus · 2023-05-09T09:29:03Z

As said: Tell us which hardware platform/constraints you are using for your docker host.

myrck · 2023-05-09T10:47:12Z

Linux 5.10.0-22-amd64 #1 SMP Debian 5.10.178-3 (2023-04-22) x86_64 GNU/Linux on an Intel Xenon CPU

Baxxy13 · 2023-05-09T10:55:27Z

cronBackup.sh calls createBackup.sh

What happens if you call createBackup.sh directly via cli?

myrck · 2023-05-09T11:00:09Z

/ # /bin/createBackup.sh 
Illegal instruction (core dumped)

myrck · 2023-05-09T11:08:48Z

I found this file. Maybe it will help:

Return-Path: <CGI script - do not reply>
From:  <CGI script - do not reply>
To: root
Subject:  CGI problem

CGI environment:
REQUEST_METHOD: GET
SCRIPT_NAME: /config/cp_security.cgi
HTTP_USER_AGENT: Mozilla/5.0 (X11; Linux x86_64; rv:102.0) Gecko/20100101 Firefox/102.0
HTTP_HOST: homematic.fritz.box
REMOTE_ADDR: 192.168.0.110
cgi.tcl version: 1.10.0
input:
sid=@04fR85ZbKW@&action=create_backup
cookie:
errorInfo:
Error connecting to peer
    while executing
"rega_script "string sd = system.GetSessionVarStr(\"$REGA_SESSION(REGASID)\");""
    (procedure "session_getsessiondata_ise" line 5)
    invoked from within
"session_getsessiondata_ise"
    (procedure "session_isvalid_ise" line 9)
    invoked from within
"session_isvalid_ise"
    (procedure "session_requestisvalid_ise" line 5)
    invoked from within
"session_requestisvalid_ise $needed_upl"
    (procedure "session_requestisvalid" line 6)
    invoked from within
"session_requestisvalid 8"
    invoked from within
"if {[session_requestisvalid 8] > 0} then action_$action"

myrck · 2023-05-09T14:03:48Z

After analyzing the script createBackup.sh I found out that the following statement fails:

/tmp # /usr/bin/sha256sum ./dutycycle.json
Illegal instruction (core dumped)
/tmp # echo $?
132

jens-maus · 2023-05-09T14:08:25Z

That sounds awkward because the sha256sum command should not run into such an Illegal instruction. Can you manually execute it to simply show the help page or does it immediately core dump? AFAICS this rather looks like a incompatibility in the way this binary is build and how it interacts on your Xeon machine. Would be great to debug this to some extend and to find out why it core dumps for you while other are not having issues with their x86_64 docker environments....

jens-maus · 2023-05-09T14:15:24Z

BTW: See here for some references in sha256sum and newer busybox versions potentially being problematic:

https://www.mail-archive.com/busybox@busybox.net/msg28790.html
https://www.mail-archive.com/busybox@busybox.net/msg28834.html
moby/buildkit@74dae15

So potentially, this would mean we need to see if the busybox folks have fixed sha256sum already and if we can grab that patch and get it fixed as well in RaspberryMatic...

jens-maus · 2023-05-09T14:19:06Z

See here for the busybox upstream bugreport which seems to be related somehow:

https://bugs.busybox.net/show_bug.cgi?id=15236

instruction on rare CPU constellations when executing sha256sum. (cf. #2309, https://bugs.busybox.net/show_bug.cgi?id=15236).

jens-maus · 2023-05-09T15:39:15Z

I just integrated the suggested patch from https://bugs.busybox.net/show_bug.cgi?id=15236. So please retest with the next nightly snapshot version appearing the upcoming nightly.

myrck · 2023-05-09T15:43:58Z

The help page is printed. I will give a feedback with the new snapshot version tomorrow.

myrck · 2023-05-10T18:29:18Z

The backup works again with the patch.

jens-maus · 2023-05-10T18:38:22Z

The backup works again with the patch.

Thanks for testing the nightly build and great that it works. Would you, however, please state which exact CPU your system uses? You just stated "Intel Xenon CPU" earlier, but I am curious which exact model this CPU is.

myrck · 2023-05-11T15:16:14Z

It is a "Intel Xeon Silver 4208".

myrck added the 🐛 bug-report Something isn't working label May 7, 2023

jens-maus added the ➡️ third-party issue This is a bug/issue for/in other third-party software label May 9, 2023

jens-maus changed the title ~~Manual and cronBackup fails~~ Manual and cronBackup fails with "Illegal instruction" May 9, 2023

jens-maus added a commit that referenced this issue May 9, 2023

integrated upstream busybox patch for potentially fixing an illegal

b8a26a7

instruction on rare CPU constellations when executing sha256sum. (cf. #2309, https://bugs.busybox.net/show_bug.cgi?id=15236).

jens-maus added the platform/oci Open Container Image (OCI) platform label May 10, 2023

jens-maus added this to the next release milestone May 10, 2023

jens-maus closed this as completed Jun 2, 2023

jens-maus modified the milestones: next release, 3.69.7.20230626 Jun 26, 2023

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Manual and cronBackup fails with "Illegal instruction" #2309

Manual and cronBackup fails with "Illegal instruction" #2309

myrck commented May 7, 2023

jens-maus commented May 8, 2023

myrck commented May 9, 2023

jens-maus commented May 9, 2023

myrck commented May 9, 2023

Baxxy13 commented May 9, 2023

myrck commented May 9, 2023

myrck commented May 9, 2023

myrck commented May 9, 2023

jens-maus commented May 9, 2023

jens-maus commented May 9, 2023

jens-maus commented May 9, 2023

jens-maus commented May 9, 2023

myrck commented May 9, 2023

myrck commented May 10, 2023

jens-maus commented May 10, 2023

myrck commented May 11, 2023

Manual and cronBackup fails with "Illegal instruction" #2309

Manual and cronBackup fails with "Illegal instruction" #2309

Comments

myrck commented May 7, 2023

Describe the issue you are experiencing

Describe the behavior you expected

Steps to reproduce the issue

What is the version this bug report is based on?

Which base platform are you running?

Which HomeMatic/homematicIP radio module are you using?

Anything in the logs that might be useful for us?

Additional information

jens-maus commented May 8, 2023

myrck commented May 9, 2023

jens-maus commented May 9, 2023

myrck commented May 9, 2023

Baxxy13 commented May 9, 2023

myrck commented May 9, 2023

myrck commented May 9, 2023

myrck commented May 9, 2023

jens-maus commented May 9, 2023

jens-maus commented May 9, 2023

jens-maus commented May 9, 2023

jens-maus commented May 9, 2023

myrck commented May 9, 2023

myrck commented May 10, 2023

jens-maus commented May 10, 2023

myrck commented May 11, 2023