Closed susilsi7 closed 3 months ago
this is found during first time execution.
I'm assuming this means, no, this isn't a regression?
Can you run this with bmcweb-logging (available in the meson options) enabled and post the result?
@raviteja-b @ratagupt can you help with above requested data . Thank you!
@edtanous Below are the requested details.
Yes, this is not regression.
Environment OpenBMC : OpenBMC Witherspoon OpenBMC Version : 2.10.0-dev-1084-g1408ee549
Note : Below results are with meson build as requested.
To Reproduce
Step 1 : Create an session
bash-4.2$ curl --insecure -X POST -D headers.txt https://${bmc_ip}/redfish/v1/SessionService/Sessions -d '{"UserName":"root", "Password":"0penBmc"}' { "@odata.id": "/redfish/v1/SessionService/Sessions/2Ekb7PO2sq", "@odata.type": "#Session.v1_3_0.Session", "ClientOriginIPAddress": "::ffff:X.X.X.X”, "Description": "Manager User Session", "Id": "2Ekb7PO2sq", "Name": "User Session", "UserName": "root" }bash-4.2$
bash-4.2$ cat headers.txt HTTP/1.1 201 Created X-Auth-Token: 51gewCuFngQ17NwZeFmM Location: /redfish/v1/SessionService/Sessions/2Ekb7PO2sq Strict-Transport-Security: max-age=31536000; includeSubdomains; preload X-Frame-Options: DENY Pragma: no-cache Cache-Control: no-Store,no-Cache X-XSS-Protection: 1; mode=block X-Content-Type-Options: nosniff Content-Security-Policy: default-src 'none'; img-src 'self' data:; font-src 'self'; style-src 'self'; script-src 'self'; connect-src 'self' wss:; form-action 'none'; frame-ancestors 'none'; plugin-types 'none'; base-uri 'none' Content-Type: application/json Date: Wed, 05 May 2021 06:05:57 GMT Content-Length: 270
bash-4.2$ export bmc_token=51gewCuFngQ17NwZeFmM
Step 2 : Perform firmware update using redfish update service URI
bash-4.2$ curl -k -H "X-Auth-Token: $bmc_token" -H "Content-Type: application/octet-stream" -X POST -T /gsa/ausgsa/projects/i/indiateam/susilsi7/GHE_IMAGES/Master/obmc-phosphor-image-witherspoon-20210505025157.ubi.mtd.tar https://${bmc_ip}/redfish/v1/UpdateService curl: (56) TCP connection reset by peer
Command Executed on BMC :
root@witherspoon-Y230UF71K02J:~# systemctl restart bmcweb
BMC Log :
May 05 06:06:44 witherspoon-Y230UF71K02J systemd[1]: Created slice system-systemd\x2dcoredump.slice.
May 05 06:06:45 witherspoon-Y230UF71K02J systemd[1]: Started Process Core Dump (PID 556/UID 0).
May 05 06:07:03 witherspoon-Y230UF71K02J systemd-coredump[557]: [LNK] Process 547 (bmcweb) of user 0 dumped core.
May 05 06:07:04 witherspoon-Y230UF71K02J systemd[1]: bmcweb.service: Main process exited, code=dumped, status=11/SEGV
May 05 06:07:04 witherspoon-Y230UF71K02J systemd[1]: bmcweb.service: Failed with result 'core-dump'.
May 05 06:07:04 witherspoon-Y230UF71K02J systemd[1]: Stopped Start bmcweb server.
May 05 06:07:04 witherspoon-Y230UF71K02J systemd[1]: Started Start bmcweb server.
May 05 06:07:04 witherspoon-Y230UF71K02J systemd[1]: systemd-coredump@0-556-0.service: Succeeded.
May 05 06:07:04 witherspoon-Y230UF71K02J bmcweb[563]: (2021-05-05 06:07:04) [DEBUG "persistent_data.hpp":108] Restored session: 08k3fQoc9qsXYYwoNcES 8C81p4JW00 xDBz1y6waf3QytziA5IB
May 05 06:07:04 witherspoon-Y230UF71K02J bmcweb[563]: (2021-05-05 06:07:04) [DEBUG "persistent_data.hpp":108] Restored session: FjFRdOw4F1K8mdHj60fE NCPAZBRJ7E Hu5CGXUMmIK8eQ6pXWqO
May 05 06:07:05 witherspoon-Y230UF71K02J bmcweb[563]: (2021-05-05 06:07:04) [DEBUG "persistent_data.hpp":127] Restored Session Timeout: 3600
May 05 06:07:05 witherspoon-Y230UF71K02J bmcweb[563]: (2021-05-05 06:07:05) [DEBUG "event_service_manager.hpp":656] EventService config not exist
May 05 06:07:05 witherspoon-Y230UF71K02J bmcweb[563]: (2021-05-05 06:07:05) [INFO "webserver_main.cpp":39] attempting systemd socket activation
May 05 06:07:05 witherspoon-Y230UF71K02J bmcweb[563]: (2021-05-05 06:07:05) [INFO "webserver_main.cpp":43] Starting webserver on socket handle 3
May 05 06:07:05 witherspoon-Y230UF71K02J bmcweb[563]: (2021-05-05 06:07:05) [ERROR "event_service_manager.hpp":1348] inotify_add_watch failed for redfish log file.
May 05 06:07:05 witherspoon-Y230UF71K02J bmcweb[563]: (2021-05-05 06:07:05) [INFO "webserver_main.cpp":133] Start Hostname Monitor Service...
May 05 06:07:05 witherspoon-Y230UF71K02J bmcweb[563]: (2021-05-05 06:07:05) [INFO "hostname_monitor.hpp":127] Register HostName PropertiesChanged Signal
May 05 06:07:05 witherspoon-Y230UF71K02J bmcweb[563]: (2021-05-05 06:07:05) [INFO "http_server.hpp":132] Building SSL Context file="/etc/ssl/certs/https/server.pem"
May 05 06:07:05 witherspoon-Y230UF71K02J bmcweb[563]: Checking certs in file /etc/ssl/certs/https/server.pem
May 05 06:07:05 witherspoon-Y230UF71K02J bmcweb[563]: Found an EC key
May 05 06:07:05 witherspoon-Y230UF71K02J bmcweb[563]: (2021-05-05 06:07:05) [DEBUG "ssl_key_handler.hpp":82] Ignoring Trust Chain error. Reason: self signed certificate
May 05 06:07:05 witherspoon-Y230UF71K02J bmcweb[563]: (2021-05-05 06:07:05) [DEBUG "ssl_key_handler.hpp":376] Using default TrustStore location: /etc/ssl/certs/authority
May 05 06:07:05 witherspoon-Y230UF71K02J bmcweb[563]: (2021-05-05 06:07:05) [INFO "app.hpp":180] app::ssl context use_count=2
May 05 06:07:05 witherspoon-Y230UF71K02J bmcweb[563]: (2021-05-05 06:07:05) [INFO "http_server.hpp":107] bmcweb server is running, local endpoint [::]:443
May 05 06:07:05 witherspoon-Y230UF71K02J bmcweb[563]: (2021-05-05 06:07:05) [DEBUG "http_connection.hpp":259] 0x17c3b28 Connection open, total 1
May 05 06:07:11 witherspoon-Y230UF71K02J systemd[1]: Starting Hostname Service...
May 05 06:07:12 witherspoon-Y230UF71K02J systemd[1]: Started Hostname Service.
May 05 06:07:14 witherspoon-Y230UF71K02J phosphor-dump-manager[559]: Wed May 5 06:07:14 UTC 2021 Report is available in /var/lib/phosphor-debug-collector/dumps/10
May 05 06:07:14 witherspoon-Y230UF71K02J phosphor-dump-manager[559]: Wed May 5 06:07:14 UTC 2021 Successfully completed
May 05 06:07:42 witherspoon-Y230UF71K02J systemd[1]: systemd-hostnamed.service: Succeeded.```
From the looks of it you only provided the last line of the actual crash. The parts of logging we need are prior to the "Stopping Start bmcweb server..." call. the failure happened before that.
BMC Log :
May 06 04:12:09 witherspoon-Y230UF71K02J bmcweb[536]: (2021-05-06 04:12:09) [DEBUG "http_connection.hpp":259] 0x238aee0 Connection open, total 2
May 06 04:12:09 witherspoon-Y230UF71K02J bmcweb[536]: (2021-05-06 04:12:09) [DEBUG "timer_queue.hpp":53] timer add inside: 0x230cab8 12
May 06 04:12:09 witherspoon-Y230UF71K02J bmcweb[536]: (2021-05-06 04:12:09) [DEBUG "http_connection.hpp":753] 0x23a3898 timer added: 0x230cab8 12
May 06 04:12:09 witherspoon-Y230UF71K02J bmcweb[536]: (2021-05-06 04:12:09) [DEBUG "http_connection.hpp":496] 0x23a3898 doReadHeaders
May 06 04:12:09 witherspoon-Y230UF71K02J bmcweb[536]: (2021-05-06 04:12:09) [ERROR "http_connection.hpp":504] 0x23a3898 async_read_header 221 Bytes
May 06 04:12:09 witherspoon-Y230UF71K02J bmcweb[536]: (2021-05-06 04:12:09) [DEBUG "http_connection.hpp":699] 0x23a3898 timer cancelled: 0x230cab8 12
May 06 04:12:09 witherspoon-Y230UF71K02J bmcweb[536]: (2021-05-06 04:12:09) [DEBUG "authorization.hpp":106] [AuthMiddleware] X-Auth-Token authentication
May 06 04:12:09 witherspoon-Y230UF71K02J bmcweb[536]: (2021-05-06 04:12:09) [DEBUG "timer_queue.hpp":53] timer add inside: 0x230cab8 13
May 06 04:12:09 witherspoon-Y230UF71K02J bmcweb[536]: (2021-05-06 04:12:09) [DEBUG "http_connection.hpp":753] 0x23a3898 timer added: 0x230cab8 13
May 06 04:12:09 witherspoon-Y230UF71K02J bmcweb[536]: (2021-05-06 04:12:09) [DEBUG "http_connection.hpp":563] Starting slow deadline
May 06 04:12:09 witherspoon-Y230UF71K02J bmcweb[536]: (2021-05-06 04:12:09) [DEBUG "http_connection.hpp":573] QueryParams:
May 06 04:12:09 witherspoon-Y230UF71K02J bmcweb[536]: (2021-05-06 04:12:09) [DEBUG "http_connection.hpp":598] 0x23a3898 doRead
May 06 04:12:11 witherspoon-Y230UF71K02J systemd[1]: Stopping Start bmcweb server...
May 06 04:12:11 witherspoon-Y230UF71K02J bmcweb[536]: (2021-05-06 04:12:11) [DEBUG "http_connection.hpp":699] 0x23a3898 timer cancelled: 0x230cab8 13
May 06 04:12:12 witherspoon-Y230UF71K02J systemd[1]: Started Process Core Dump (PID 546/UID 0).
May 06 04:12:38 witherspoon-Y230UF71K02J systemd-coredump[547]: Cannot store coredump of 536 (bmcweb): No space left on device
May 06 04:12:38 witherspoon-Y230UF71K02J systemd-coredump[547]: [LNK] Process 536 (bmcweb) of user 0 dumped core.
May 06 04:12:38 witherspoon-Y230UF71K02J systemd[1]: bmcweb.service: Main process exited, code=dumped, status=11/SEGV
May 06 04:12:38 witherspoon-Y230UF71K02J systemd[1]: bmcweb.service: Failed with result 'core-dump'.
May 06 04:12:38 witherspoon-Y230UF71K02J systemd[1]: Stopped Start bmcweb server.
May 06 04:12:38 witherspoon-Y230UF71K02J systemd[1]: Started Start bmcweb server.
May 06 04:12:38 witherspoon-Y230UF71K02J systemd[1]: systemd-coredump@1-546-0.service: Succeeded.
May 06 04:12:39 witherspoon-Y230UF71K02J bmcweb[548]: (2021-05-06 04:12:39) [ERROR "sessions.hpp":112] Got unexpected property reading persistent file: client_id
May 06 04:12:39 witherspoon-Y230UF71K02J bmcweb[548]: (2021-05-06 04:12:39) [DEBUG "persistent_data.hpp":108] Restored session: RSpzMr1VkIqg60RkSLYB sapPRrZayu aclxqJeoCpSNntjER6hS
May 06 04:12:39 witherspoon-Y230UF71K02J bmcweb[548]: (2021-05-06 04:12:39) [DEBUG "persistent_data.hpp":127] Restored Session Timeout: 3600
May 06 04:12:39 witherspoon-Y230UF71K02J bmcweb[548]: (2021-05-06 04:12:39) [DEBUG "event_service_manager.hpp":656] EventService config not exist
May 06 04:12:39 witherspoon-Y230UF71K02J bmcweb[548]: (2021-05-06 04:12:39) [INFO "webserver_main.cpp":39] attempting systemd socket activation
May 06 04:12:39 witherspoon-Y230UF71K02J bmcweb[548]: (2021-05-06 04:12:39) [INFO "webserver_main.cpp":43] Starting webserver on socket handle 3
May 06 04:12:39 witherspoon-Y230UF71K02J bmcweb[548]: (2021-05-06 04:12:39) [ERROR "event_service_manager.hpp":1348] inotify_add_watch failed for redfish log file.
May 06 04:12:39 witherspoon-Y230UF71K02J bmcweb[548]: (2021-05-06 04:12:39) [INFO "webserver_main.cpp":133] Start Hostname Monitor Service...
May 06 04:12:39 witherspoon-Y230UF71K02J bmcweb[548]: (2021-05-06 04:12:39) [INFO "hostname_monitor.hpp":127] Register HostName PropertiesChanged Signal
May 06 04:12:39 witherspoon-Y230UF71K02J bmcweb[548]: (2021-05-06 04:12:39) [INFO "http_server.hpp":132] Building SSL Context file="/etc/ssl/certs/https/server.pem"
May 06 04:12:39 witherspoon-Y230UF71K02J bmcweb[548]: Checking certs in file /etc/ssl/certs/https/server.pem
May 06 04:12:39 witherspoon-Y230UF71K02J bmcweb[548]: Found an EC key
May 06 04:12:39 witherspoon-Y230UF71K02J bmcweb[548]: (2021-05-06 04:12:39) [DEBUG "ssl_key_handler.hpp":82] Ignoring Trust Chain error. Reason: self signed certificate
May 06 04:12:39 witherspoon-Y230UF71K02J bmcweb[548]: (2021-05-06 04:12:39) [DEBUG "ssl_key_handler.hpp":376] Using default TrustStore location: /etc/ssl/certs/authority
May 06 04:12:39 witherspoon-Y230UF71K02J bmcweb[548]: (2021-05-06 04:12:39) [INFO "app.hpp":180] app::ssl context use_count=2
May 06 04:12:39 witherspoon-Y230UF71K02J bmcweb[548]: (2021-05-06 04:12:39) [INFO "http_server.hpp":107] bmcweb server is running, local endpoint [::]:443
May 06 04:12:39 witherspoon-Y230UF71K02J bmcweb[548]: (2021-05-06 04:12:39) [DEBUG "http_connection.hpp":259] 0x1b2b998 Connection open, total 1```
@edtanous does the above info helps ?
@gkeishin @susilsi7 Still a problem?
BMC Log:
Oct 06 05:21:22 witherspoon-Y230UF71K02J systemd[1]: Finished Updates the u-boot variable to point BMC version to 6e8b6e09.
Oct 06 05:21:35 witherspoon-Y230UF71K02J systemd[1]: Stopping Start bmcweb server...
Oct 06 05:21:35 witherspoon-Y230UF71K02J bmcweb[191]: free(): double free detected in tcache 2
Oct 06 05:21:36 witherspoon-Y230UF71K02J obmc-flash-bmc[664]: Volume ID 0, size 300 LEBs (19622400 bytes, 18.7 MiB), LEB size 65408 bytes (63.8 KiB), static, name "rofs-e7d69467", alignment 1
Oct 06 05:21:37 witherspoon-Y230UF71K02J obmc-flash-bmc[702]: ubiupdatevol: error!: stat failed on "/tmp/images/e7d69467/image-rofs"
Oct 06 05:21:37 witherspoon-Y230UF71K02J systemd[1]: obmc-flash-bmc-ubiro@e7d69467.service: Main process exited, code=exited, status=255/EXCEPTION
Oct 06 05:21:37 witherspoon-Y230UF71K02J systemd[1]: obmc-flash-bmc-ubiro@e7d69467.service: Failed with result 'exit-code'.
Oct 06 05:21:37 witherspoon-Y230UF71K02J systemd[1]: Failed to start Store read-only images e7d69467 to BMC storage.
Oct 06 05:21:37 witherspoon-Y230UF71K02J systemd[1]: obmc-flash-bmc-ubiro@e7d69467.service: Triggering OnFailure= dependencies.
Oct 06 05:21:38 witherspoon-Y230UF71K02J systemd[1]: Created slice Slice /system/systemd-coredump.
Oct 06 05:21:38 witherspoon-Y230UF71K02J systemd[1]: Starting Deletes read-only and kernel ubi volume e7d69467...
Oct 06 05:21:38 witherspoon-Y230UF71K02J systemd[1]: Started Process Core Dump (PID 696/UID 0).
Oct 06 05:21:40 witherspoon-Y230UF71K02J systemd[1]: obmc-flash-bmc-ubiro-remove@e7d69467.service: Deactivated successfully.
Oct 06 05:21:40 witherspoon-Y230UF71K02J systemd[1]: Finished Deletes read-only and kernel ubi volume e7d69467.
Oct 06 05:22:24 witherspoon-Y230UF71K02J health-monitor[224]: ASSERT: Utilization Sensor has exceeded critical high threshold
Oct 06 05:23:05 witherspoon-Y230UF71K02J systemd[1]: bmcweb.service: State 'stop-sigterm' timed out. Killing.
Oct 06 05:23:05 witherspoon-Y230UF71K02J systemd[1]: bmcweb.service: Killing process 191 (bmcweb) with signal SIGKILL.
Oct 06 05:23:05 witherspoon-Y230UF71K02J systemd[1]: bmcweb.service: Main process exited, code=killed, status=9/KILL
Oct 06 05:23:05 witherspoon-Y230UF71K02J systemd[1]: bmcweb.service: Failed with result 'timeout'.
Oct 06 05:23:05 witherspoon-Y230UF71K02J systemd[1]: Stopped Start bmcweb server.
Oct 06 05:23:05 witherspoon-Y230UF71K02J systemd[1]: Started Start bmcweb server.
Oct 06 05:23:44 witherspoon-Y230UF71K02J systemd-coredump[704]: Failed to compress (unnamed temporary file): No space left on device
Oct 06 05:23:44 witherspoon-Y230UF71K02J systemd-coredump[704]: [LNK] Process 191 (bmcweb) of user 0 dumped core.
Oct 06 05:23:45 witherspoon-Y230UF71K02J systemd[1]: systemd-coredump@0-696-0.service: Deactivated successfully.
Oct 06 05:23:59 witherspoon-Y230UF71K02J health-monitor[224]: DEASSERT: Utilization Sensor is under critical high threshold
Oct 06 05:26:43 witherspoon-Y230UF71K02J systemd[1]: Starting Cleanup of Temporary Directories...
Oct 06 05:26:43 witherspoon-Y230UF71K02J systemd-tmpfiles[724]: /etc/tmpfiles.d/pam.conf:1: Line references path below legacy directory /var/run/, updating /var/run/sepermit → /run/sepermit; please update the tmpfiles.d/ drop-in file accordingly.
Oct 06 05:26:43 witherspoon-Y230UF71K02J systemd[1]: systemd-tmpfiles-clean.service: Deactivated successfully.
Oct 06 05:26:43 witherspoon-Y230UF71K02J systemd[1]: Finished Cleanup of Temporary Directories.
Firmware Version : VERSION_ID=2.11.0-dev-1124-g1167ada3a
This is likely due to shutting down the dbus connection while there are active match expressions active, and there being an implicit ownership between the two that we're not handling properly. Because the instructions involve logging into an internal API (ssh/serial) and intentionally shutting down bmcweb, and the end user result is the same (sockets drop, service becomes unavailable) this isn't an extremely high priority for me personally. Happy to accept patches to fix this though.
Anyone interested in tackling this?
Anyone interested in tackling this?
@susilsi7 @gkeishin can you please check if you are still noticing same issue on latest builds?
@susilsi7 @gkeishin Is this still a problem? If not, let's close
yes, this is still a problem.
Closing due to inactivity. No attempts to resolve this have been pushed in 3 years; Clearly it's not a problem in practice.
Describe the bug bmcweb code dump seen when bmcweb restarted during firmware update
Environment OpenBMC : OpenBMC Witherspoon OpenBMC Version : 2.10.0-dev-995-g43a03d276
To Reproduce
Step 1 : Create an session
bash-4.2$ curl --insecure -X POST -D headers.txt https://${bmc_ip}/redfish/v1/SessionService/Sessions -d '{"UserName":"root", "Password":"0penBmc"}' { "@odata.id": "/redfish/v1/SessionService/Sessions/au2zszQgl2", "@odata.type": "#Session.v1_3_0.Session", "ClientOriginIPAddress": "::ffff:X.X.X.X", "Description": "Manager User Session", "Id": "au2zszQgl2", "Name": "User Session", "Oem": { "OpenBMC": { "@odata.type": "#OemSession.v1_0_0.Session", "ClientID": "" } }, "UserName": "root" }
bash-4.2$cat headers.txt HTTP/1.1 201 Created X-Auth-Token: 9NQgRGts0O3IINAgwgWD Location: /redfish/v1/SessionService/Sessions/au2zszQgl2 Strict-Transport-Security: max-age=31536000; includeSubdomains; preload X-Frame-Options: DENY Pragma: no-cache Cache-Control: no-Store,no-Cache X-XSS-Protection: 1; mode=block X-Content-Type-Options: nosniff Content-Security-Policy: default-src 'none'; img-src 'self' data:; font-src 'self'; style-src 'self'; script-src 'self'; connect-src 'self' wss:; form-action 'none'; frame-ancestors 'none'; plugin-types 'none'; base-uri 'none' Content-Type: application/json Date: Wed, 28 Apr 2021 07:38:40 GMT Content-Length: 381
bash-4.2$ export bmc_token=9NQgRGts0O3IINAgwgWD
Step 2 : Perform firmware update using redfish update service URI
bash-4.2$ curl -k -H "X-Auth-Token: $bmc_token" -H "Content-Type: application/octet-stream" -X POST -T ./obmc-phosphor-image-witherspoon-20210426025132.ubi.mtd.tar https://${bmc_ip}/redfish/v1/UpdateService curl: (56) TCP connection reset by peer bash-4.2$
Command Executed on BMC :
root@witherspoon-Y230UF71K02J:~# systemctl restart bmcweb
BMC Log :
Is this a regression this is found during first time execution.