Runner 13.12 / pwsh / unicode - can cause a 'source sequence is illegal/malformed utf-8' 500 error in rails
Summary
While reproducing #27842 (closed) I noticed that job logs were failing to display.
A unicode character is being corrupted when being passed via STDIN to pwsh. The resulting character(s), when printed to the job log, are causing a failure in Rails.
But not with the 13.10 and 13.11 runners, only 13.12 beta.
For the reproduction of the other issue, I worked around it by using an artifact to store the corrupted characters. The reproduction here includes the artifacts for reference, as well as the output in the job log.
Steps to reproduce
https://gitlab.com/bprescott-support/testing/zd206695-unicode_ux_fail
Actual behavior
Job log fails to display
Expected behavior
Job log displays
Relevant logs and/or screenshots
from https://gitlab.com/bprescott-support/testing/zd206695-unicode_ux_fail/-/pipelines/298344774
13.11 log - Running with gitlab-runner 13.11.0 (7f7a4bb0)
13.12 log - Running with gitlab-runner 13.12.0~beta.38.g8b66b0c7 (8b66b0c7)
it's the same input character, as the hex output is the same. But the ascii rendering is different.
$ ls *raw.log | while read f ; do echo $f ; cat -vet $f | egrep 'C3 94 C3 AA C3 A0|E2 88 85' ; done
1311-raw.log
0000000000000000 C3 94 C3 AA C3 A0 M-oM-?M-=?M-GM-&M-oM-?M-=M-oM-?M-=^M$
0000000000000000 E2 88 85 M-oM-?M-=??^M$
1312-raw.log
0000000000000000 C3 94 C3 AA C3 A0 M-G?M-GM-&M-GM-^?^M$
0000000000000000 E2 88 85 M-^C??^M$from self managed, 13.11.3
here's the log entries for the correlation ID associated with trying to access the job log.
The UI error is a Rails 500 error on the back end, part of which is:
"exception.class": "JSON::GeneratorError",
"exception.message": "source sequence is illegal/malformed utf-8",
"exception.backtrace": [
"app/controllers/application_controller.rb:123:in `render'",
"app/controllers/projects/jobs_controller.rb:61:in `block (3 levels) in trace'",
"app/controllers/projects/jobs_controller.rb:54:in `block in trace'",
"lib/gitlab/ci/trace.rb:161:in `read_stream'",
"lib/gitlab/ci/trace.rb:84:in `read'",
"app/controllers/projects/jobs_controller.rb:53:in `trace'",
"ee/lib/gitlab/ip_address_state.rb:10:in `with'",workhorse
{
"content_type": "text/html; charset=utf-8",
"correlation_id": "01F50HHC4YYJKH173ZSFSG7SRY",
"duration_ms": 689,
"host": "gitlab.example.com",
"level": "info",
"method": "GET",
"msg": "access",
"proto": "HTTP/1.1",
"referrer": "https://gitlab.example.com/test/zd206695-unicode_ux_fail/-/jobs/13412",
"remote_addr": "127.0.0.1:0",
"remote_ip": "127.0.0.1",
"route": "",
"status": 500,
"system": "http",
"time": "2021-05-06T10:53:28+01:00",
"ttfb_ms": 689,
"uri": "/test/zd206695-unicode_ux_fail/-/jobs/13412/trace.json?state=",
"user_agent": "Mozilla/5.0 (X11; Ubuntu; Linux x86_64; rv:88.0) Gecko/20100101 Firefox/88.0",
"written_bytes": 2926
}
gitaly
{
"correlation_id": "01F50HHC4YYJKH173ZSFSG7SRY",
"grpc.code": "OK",
"grpc.meta.auth_version": "v2",
"grpc.meta.client_name": "gitlab-web",
"grpc.meta.deadline_type": "regular",
"grpc.method": "ListCommitsByOid",
"grpc.request.deadline": "2021-05-06T09:53:58.050Z",
"grpc.request.fullMethod": "/gitaly.CommitService/ListCommitsByOid",
"grpc.request.glProjectPath": "test/zd206695-unicode_ux_fail",
"grpc.request.glRepository": "project-83",
"grpc.request.repoPath": "@hashed/bb/b9/bbb965ab0c80d6538cf2184babad2a564a010376712012bd07b0af92dcd3097d.git",
"grpc.request.repoStorage": "default",
"grpc.request.topLevelGroup": "@hashed",
"grpc.service": "gitaly.CommitService",
"grpc.start_time": "2021-05-06T09:53:28.250Z",
"grpc.time_ms": 10.554,
"level": "info",
"msg": "finished streaming call with code OK",
"peer.address": "@",
"pid": 15886,
"remote_ip": "192.168.1.68",
"span.kind": "server",
"system": "grpc",
"time": "2021-05-06T09:53:28.260Z",
"username": "root"
}
{
"command.count": 1,
"command.inblock": 0,
"command.majflt": 0,
"command.maxrss": 35292,
"command.minflt": 381,
"command.oublock": 0,
"command.real_time_ms": 18,
"command.system_time_ms": 1,
"command.user_time_ms": 0,
"correlation_id": "01F50HHC4YYJKH173ZSFSG7SRY",
"grpc.code": "OK",
"grpc.meta.auth_version": "v2",
"grpc.meta.client_name": "gitlab-web",
"grpc.meta.deadline_type": "regular",
"grpc.method": "FindAllTagNames",
"grpc.request.deadline": "2021-05-06T09:53:38.005Z",
"grpc.request.fullMethod": "/gitaly.RefService/FindAllTagNames",
"grpc.request.glProjectPath": "test/zd206695-unicode_ux_fail",
"grpc.request.glRepository": "project-83",
"grpc.request.repoPath": "@hashed/bb/b9/bbb965ab0c80d6538cf2184babad2a564a010376712012bd07b0af92dcd3097d.git",
"grpc.request.repoStorage": "default",
"grpc.request.topLevelGroup": "@hashed",
"grpc.service": "gitaly.RefService",
"grpc.start_time": "2021-05-06T09:53:28.265Z",
"grpc.time_ms": 19.253,
"level": "info",
"msg": "finished streaming call with code OK",
"peer.address": "@",
"pid": 15886,
"remote_ip": "192.168.1.68",
"span.kind": "server",
"system": "grpc",
"time": "2021-05-06T09:53:28.284Z",
"username": "root"
}
{
"command.count": 1,
"command.inblock": 0,
"command.majflt": 0,
"command.maxrss": 35292,
"command.minflt": 381,
"command.oublock": 0,
"command.real_time_ms": 3,
"command.system_time_ms": 0,
"command.user_time_ms": 2,
"correlation_id": "01F50HHC4YYJKH173ZSFSG7SRY",
"grpc.code": "OK",
"grpc.meta.auth_version": "v2",
"grpc.meta.client_name": "gitlab-web",
"grpc.meta.deadline_type": "regular",
"grpc.method": "FindAllTagNames",
"grpc.request.deadline": "2021-05-06T09:53:38.001Z",
"grpc.request.fullMethod": "/gitaly.RefService/FindAllTagNames",
"grpc.request.glProjectPath": "test/zd206695-unicode_ux_fail",
"grpc.request.glRepository": "project-83",
"grpc.request.repoPath": "@hashed/bb/b9/bbb965ab0c80d6538cf2184babad2a564a010376712012bd07b0af92dcd3097d.git",
"grpc.request.repoStorage": "default",
"grpc.request.topLevelGroup": "@hashed",
"grpc.service": "gitaly.RefService",
"grpc.start_time": "2021-05-06T09:53:28.351Z",
"grpc.time_ms": 3.444,
"level": "info",
"msg": "finished streaming call with code OK",
"peer.address": "@",
"pid": 15886,
"remote_ip": "192.168.1.68",
"span.kind": "server",
"system": "grpc",
"time": "2021-05-06T09:53:28.354Z",
"username": "root"
}
rails
{
"method": "GET",
"path": "/test/zd206695-unicode_ux_fail/-/jobs/13412/trace.json",
"format": "json",
"controller": "Projects::JobsController",
"action": "trace",
"status": 500,
"time": "2021-05-06T09:53:28.392Z",
"params": [
{
"key": "state",
"value": ""
},
{
"key": "namespace_id",
"value": "test"
},
{
"key": "project_id",
"value": "zd206695-unicode_ux_fail"
},
{
"key": "id",
"value": "13412"
}
],
"remote_ip": "192.168.1.68",
"user_id": 1,
"username": "root",
"ua": "Mozilla/5.0 (X11; Ubuntu; Linux x86_64; rv:88.0) Gecko/20100101 Firefox/88.0",
"correlation_id": "01F50HHC4YYJKH173ZSFSG7SRY",
"meta.user": "root",
"meta.project": "test/zd206695-unicode_ux_fail",
"meta.root_namespace": "test",
"meta.caller_id": "Projects::JobsController#trace",
"meta.remote_ip": "192.168.1.68",
"meta.feature_category": "continuous_integration",
"meta.client_id": "user/1",
"gitaly_calls": 3,
"gitaly_duration_s": 0.039093,
"redis_calls": 8,
"redis_duration_s": 0.012473999999999999,
"redis_read_bytes": 1279,
"redis_write_bytes": 2282,
"redis_cache_calls": 7,
"redis_cache_duration_s": 0.010305,
"redis_cache_read_bytes": 998,
"redis_cache_write_bytes": 1582,
"redis_shared_state_calls": 1,
"redis_shared_state_duration_s": 0.002169,
"redis_shared_state_read_bytes": 281,
"redis_shared_state_write_bytes": 700,
"db_count": 39,
"db_write_count": 0,
"db_cached_count": 5,
"cpu_s": 0.259014,
"mem_objects": 82246,
"mem_bytes": 12560192,
"mem_mallocs": 21852,
"queue_duration_s": 0.023473,
"exception.class": "JSON::GeneratorError",
"exception.message": "source sequence is illegal/malformed utf-8",
"exception.backtrace": [
"app/controllers/application_controller.rb:123:in `render'",
"app/controllers/projects/jobs_controller.rb:61:in `block (3 levels) in trace'",
"app/controllers/projects/jobs_controller.rb:54:in `block in trace'",
"lib/gitlab/ci/trace.rb:161:in `read_stream'",
"lib/gitlab/ci/trace.rb:84:in `read'",
"app/controllers/projects/jobs_controller.rb:53:in `trace'",
"ee/lib/gitlab/ip_address_state.rb:10:in `with'",
"ee/app/controllers/ee/application_controller.rb:44:in `set_current_ip_address'",
"app/controllers/application_controller.rb:485:in `set_current_admin'",
"lib/gitlab/session.rb:11:in `with_session'",
"app/controllers/application_controller.rb:476:in `set_session_storage'",
"lib/gitlab/i18n.rb:73:in `with_locale'",
"lib/gitlab/i18n.rb:79:in `with_user_locale'",
"app/controllers/application_controller.rb:470:in `set_locale'",
"app/controllers/application_controller.rb:463:in `block in set_current_context'",
"lib/gitlab/application_context.rb:70:in `block in use'",
"lib/gitlab/application_context.rb:70:in `use'",
"lib/gitlab/application_context.rb:27:in `with_context'",
"app/controllers/application_controller.rb:454:in `set_current_context'",
"lib/gitlab/metrics/elasticsearch_rack_middleware.rb:16:in `call'",
"lib/gitlab/middleware/rails_queue_duration.rb:33:in `call'",
"lib/gitlab/metrics/rack_middleware.rb:16:in `block in call'",
"lib/gitlab/metrics/transaction.rb:56:in `run'",
"lib/gitlab/metrics/rack_middleware.rb:16:in `call'",
"lib/gitlab/request_profiler/middleware.rb:17:in `call'",
"lib/gitlab/jira/middleware.rb:19:in `call'",
"lib/gitlab/middleware/go.rb:20:in `call'",
"lib/gitlab/etag_caching/middleware.rb:21:in `call'",
"lib/gitlab/middleware/multipart.rb:172:in `call'",
"lib/gitlab/middleware/read_only/controller.rb:50:in `call'",
"lib/gitlab/middleware/read_only.rb:18:in `call'",
"lib/gitlab/middleware/same_site_cookies.rb:27:in `call'",
"lib/gitlab/middleware/handle_malformed_strings.rb:21:in `call'",
"lib/gitlab/middleware/basic_health_check.rb:25:in `call'",
"lib/gitlab/middleware/handle_ip_spoof_attack_error.rb:25:in `call'",
"lib/gitlab/middleware/request_context.rb:21:in `call'",
"config/initializers/fix_local_cache_middleware.rb:11:in `call'",
"lib/gitlab/middleware/rack_multipart_tempfile_factory.rb:21:in `call'",
"lib/gitlab/metrics/requests_rack_middleware.rb:76:in `call'",
"lib/gitlab/middleware/release_env.rb:12:in `call'"
],
"db_duration_s": 0.18725,
"view_duration_s": 0,
"duration_s": 0.6351
}
Environment description
GitLab 13.11.3 used to reproduce self-managed, 13.12.0-pre 7d24854f5fe for dotcom
Used GitLab Runner version
I have a Windows 10 laptop with multiple runners set up as services. Reproduced using Powershell 7.0.6 (See job output for version)
All are configured with the defaults except for check_interval
concurrent = 1
check_interval = 13
[session_server]
session_timeout = 1800
[[runners]]
name = "foo"
url = "https://gitlab.com"
token = "bar"
executor = "shell"
shell = "pwsh"Possible fixes
Edited by Ben Prescott_