spark icon indicating copy to clipboard operation
spark copied to clipboard
verified publisher icon apache

[SPARK-49015][CORE] Connect Server should respect `spark.log.structuredLogging.enabled`

Open pan3793 opened this issue 1 year ago • 13 comments

What changes were proposed in this pull request?

Currently, structured logging is constantly activated no matter value of spark.log.structuredLogging.enabled.

Why are the changes needed?

Bug fix, to make spark.log.structuredLogging.enabled works with connect server.

Does this PR introduce any user-facing change?

No, structured logging is an unreleased feature.

How was this patch tested?

sbin/start-connect-server.sh --conf spark.log.structuredLogging.enabled=true

starting org.apache.spark.sql.connect.service.SparkConnectServer, logging to /home/chengpan/Projects/apache-spark/logs/spark-chengpan-org.apache.spark.sql.connect.service.SparkConnectServer-1-HIH-D-25944Z.out
Spark Command: /home/chengpan/.sdkman/candidates/java/current/bin/java -cp hive-jackson/*:/home/chengpan/Projects/apache-spark/conf/:/home/chengpan/Projects/apache-spark/assembly/target/scala-2.13/jars/slf4j-api-2.0.13.jar:/home/chengpan/Projects/apache-spark/assembly/target/scala-2.13/jars/* -Xmx1g -XX:+IgnoreUnrecognizedVMOptions --add-modules=jdk.incubator.vector --add-opens=java.base/java.lang=ALL-UNNAMED --add-opens=java.base/java.lang.invoke=ALL-UNNAMED --add-opens=java.base/java.lang.reflect=ALL-UNNAMED --add-opens=java.base/java.io=ALL-UNNAMED --add-opens=java.base/java.net=ALL-UNNAMED --add-opens=java.base/java.nio=ALL-UNNAMED --add-opens=java.base/java.util=ALL-UNNAMED --add-opens=java.base/java.util.concurrent=ALL-UNNAMED --add-opens=java.base/java.util.concurrent.atomic=ALL-UNNAMED --add-opens=java.base/jdk.internal.ref=ALL-UNNAMED --add-opens=java.base/sun.nio.ch=ALL-UNNAMED --add-opens=java.base/sun.nio.cs=ALL-UNNAMED --add-opens=java.base/sun.security.action=ALL-UNNAMED --add-opens=java.base/sun.util.calendar=ALL-UNNAMED --add-opens=java.security.jgss/sun.security.krb5=ALL-UNNAMED -Djdk.reflect.useDirectMethodHandle=false -Dio.netty.tryReflectionSetAccessible=true -Dderby.connection.requireAuthentication=false org.apache.spark.deploy.SparkSubmit --conf spark.log.structuredLogging.enabled=true --class org.apache.spark.sql.connect.service.SparkConnectServer --name Spark Connect server spark-internal
========================================
WARNING: Using incubator modules: jdk.incubator.vector
Using Spark's default log4j profile: org/apache/spark/log4j2-defaults.properties
{"ts":"2024-07-26T11:40:40.779Z","level":"WARN","msg":"Your hostname, HIH-D-25944Z, resolves to a loopback address: 127.0.1.1; using 10.219.36.108 instead (on interface enp2s0)","context":{"host":"HIH-D-25944Z","host_port":"127.0.1.1","host_port2":"10.219.36.108","network_if":"enp2s0"},"logger":"Utils"}
{"ts":"2024-07-26T11:40:40.782Z","level":"WARN","msg":"Set SPARK_LOCAL_IP if you need to bind to another address","logger":"Utils"}
Using Spark's default log4j profile: org/apache/spark/log4j2-defaults.properties
{"ts":"2024-07-26T11:40:41.044Z","level":"INFO","msg":"Starting Spark session.","logger":"SparkConnectServer"}
{"ts":"2024-07-26T11:40:41.067Z","level":"INFO","msg":"Running Spark version 4.0.0-SNAPSHOT","context":{"spark_version":"4.0.0-SNAPSHOT"},"logger":"SparkContext"}
{"ts":"2024-07-26T11:40:41.068Z","level":"INFO","msg":"OS info Linux, 6.5.0-44-generic, amd64","context":{"os_arch":"amd64","os_name":"Linux","os_version":"6.5.0-44-generic"},"logger":"SparkContext"}
{"ts":"2024-07-26T11:40:41.069Z","level":"INFO","msg":"Java version 17.0.8","context":{"java_version":"17.0.8"},"logger":"SparkContext"}
...

sbin/start-connect-server.sh --conf spark.log.structuredLogging.enabled=false

starting org.apache.spark.sql.connect.service.SparkConnectServer, logging to /home/chengpan/Projects/apache-spark/logs/spark-chengpan-org.apache.spark.sql.connect.service.SparkConnectServer-1-HIH-D-25944Z.out
Spark Command: /home/chengpan/.sdkman/candidates/java/current/bin/java -cp hive-jackson/*:/home/chengpan/Projects/apache-spark/conf/:/home/chengpan/Projects/apache-spark/assembly/target/scala-2.13/jars/slf4j-api-2.0.13.jar:/home/chengpan/Projects/apache-spark/assembly/target/scala-2.13/jars/* -Xmx1g -XX:+IgnoreUnrecognizedVMOptions --add-modules=jdk.incubator.vector --add-opens=java.base/java.lang=ALL-UNNAMED --add-opens=java.base/java.lang.invoke=ALL-UNNAMED --add-opens=java.base/java.lang.reflect=ALL-UNNAMED --add-opens=java.base/java.io=ALL-UNNAMED --add-opens=java.base/java.net=ALL-UNNAMED --add-opens=java.base/java.nio=ALL-UNNAMED --add-opens=java.base/java.util=ALL-UNNAMED --add-opens=java.base/java.util.concurrent=ALL-UNNAMED --add-opens=java.base/java.util.concurrent.atomic=ALL-UNNAMED --add-opens=java.base/jdk.internal.ref=ALL-UNNAMED --add-opens=java.base/sun.nio.ch=ALL-UNNAMED --add-opens=java.base/sun.nio.cs=ALL-UNNAMED --add-opens=java.base/sun.security.action=ALL-UNNAMED --add-opens=java.base/sun.util.calendar=ALL-UNNAMED --add-opens=java.security.jgss/sun.security.krb5=ALL-UNNAMED -Djdk.reflect.useDirectMethodHandle=false -Dio.netty.tryReflectionSetAccessible=true -Dderby.connection.requireAuthentication=false org.apache.spark.deploy.SparkSubmit --conf spark.log.structuredLogging.enabled=false --class org.apache.spark.sql.connect.service.SparkConnectServer --name Spark Connect server spark-internal
========================================
WARNING: Using incubator modules: jdk.incubator.vector
Using Spark's default log4j profile: org/apache/spark/log4j2-defaults.properties
{"ts":"2024-07-26T11:41:23.459Z","level":"WARN","msg":"Your hostname, HIH-D-25944Z, resolves to a loopback address: 127.0.1.1; using 10.219.36.108 instead (on interface enp2s0)","context":{"host":"HIH-D-25944Z","host_port":"127.0.1.1","host_port2":"10.219.36.108","network_if":"enp2s0"},"logger":"Utils"}
{"ts":"2024-07-26T11:41:23.463Z","level":"WARN","msg":"Set SPARK_LOCAL_IP if you need to bind to another address","logger":"Utils"}
Using Spark's default log4j profile: org/apache/spark/log4j2-pattern-layout-defaults.properties
24/07/26 19:41:23 INFO SparkConnectServer: Starting Spark session.
24/07/26 19:41:23 INFO SparkContext: Running Spark version 4.0.0-SNAPSHOT
24/07/26 19:41:23 INFO SparkContext: OS info Linux, 6.5.0-44-generic, amd64
24/07/26 19:41:23 INFO SparkContext: Java version 17.0.8
...

Was this patch authored or co-authored using generative AI tooling?

No.

pan3793 avatar Jul 26 '24 11:07 pan3793

cc @gengliangwang @HyukjinKwon

pan3793 avatar Jul 26 '24 14:07 pan3793

hm, this works to be without this change:

sbin/start-connect-server.sh --conf spark.log.structuredLogging.enabled=false
starting org.apache.spark.sql.connect.service.SparkConnectServer, logging to /.../spark/logs/spark-hyukjin.kwon-org.apache.spark.sql.connect.service.SparkConnectServer-1-GF2HX736Y2.out
tail -f /.../spark/logs/spark-hyukjin.kwon-org.apache.spark.sql.connect.service.SparkConnectServer-1-GF2HX736Y2.out

24/07/27 16:02:11 INFO ContextHandler: Started o.e.j.s.ServletContextHandler@70029d2d{/metrics,null,AVAILABLE,@Spark}
24/07/27 16:02:11 INFO ContextHandler: Started o.e.j.s.ServletContextHandler@654e6a90{/jobs/job/kill,null,AVAILABLE,@Spark}
24/07/27 16:02:11 INFO ContextHandler: Started o.e.j.s.ServletContextHandler@16a5c7e4{/stages/stage/kill,null,AVAILABLE,@Spark}
24/07/27 16:02:11 INFO ContextHandler: Started o.e.j.s.ServletContextHandler@1e957e2f{/metrics/json,null,AVAILABLE,@Spark}
24/07/27 16:02:11 INFO Utils: Successfully started service 'org.apache.spark.sql.connect.service.SparkConnectService$' on port 15002.
24/07/27 16:02:11 INFO ContextHandler: Started o.e.j.s.ServletContextHandler@4a642e4b{/connect,null,AVAILABLE,@Spark}
24/07/27 16:02:11 INFO ContextHandler: Started o.e.j.s.ServletContextHandler@3b4086c1{/connect/json,null,AVAILABLE,@Spark}
24/07/27 16:02:11 INFO ContextHandler: Started o.e.j.s.ServletContextHandler@5eed6dfb{/connect/session,null,AVAILABLE,@Spark}
24/07/27 16:02:11 INFO ContextHandler: Started o.e.j.s.ServletContextHandler@551be9f6{/connect/session/json,null,AVAILABLE,@Spark}
24/07/27 16:02:11 INFO SparkConnectServer: Spark Connect server started at: 0:0:0:0:0:0:0:0:15002

HyukjinKwon avatar Jul 27 '24 20:07 HyukjinKwon

kindly ping @gengliangwang

pan3793 avatar Aug 06 '24 02:08 pan3793

some of GHA workflows are outdated, rebased on master

pan3793 avatar Aug 26 '24 04:08 pan3793

@gengliangwang issue still exists, verified the latest master branch d64d1f76ff28f97db0ad3f3647ae2683e80095a2

$ dev/make-distribution.sh
$ cd dist
$ SPARK_NO_DAEMONIZE=1 sbin/start-connect-server.sh --conf spark.log.structuredLogging.enabled=false
image

pan3793 avatar Aug 27 '24 03:08 pan3793

@pan3793 I tried and can't reproduce your issue. Please make sure there is no changes in dist/conf/ which may change the logging behavior.

$ dev/make-distribution.sh
$ cd dist
$ SPARK_NO_DAEMONIZE=1 sbin/start-connect-server.sh --conf spark.log.structuredLogging.enabled=false
image

gengliangwang avatar Aug 27 '24 05:08 gengliangwang

Please make sure there is no changes in dist/conf/ which may change the logging behavior.

I had checked that, and it definitely has no change. I also checked env | grep SPARK_, no unexpected settings.

pan3793 avatar Aug 27 '24 05:08 pan3793

@gengliangwang I notice a difference, seems your log does not have

Using Spark's default log4j profile: org/apache/spark/log4j2-defaults.properties

or

Using Spark's default log4j profile: org/apache/spark/log4j2-pattern-layout-defaults.properties

while my log has, this should indicate 1) that the initializeLogging is called by different places with silent true and false, or 2) your log4j does not load the spark default configuration

pan3793 avatar Aug 27 '24 05:08 pan3793 

sbin/start-connect-server.sh --conf spark.log.structuredLogging.enabled=false

I used the command dev/make-distribution.sh --tgz -Phive to package the latest code.

And without this pr, I manually run sbin/start-connect-server.sh --conf spark.log.structuredLogging.enabled=false, and it did use structuredLogging, even though spark.log.structuredLogging.enabled was specified as false:

tail -100f logs/spark-yangjie01-org.apache.spark.sql.connect.service.SparkConnectServer-1-MacBook-Pro.local.out

Spark Command: /Users/yangjie01/Tools/zulu17/bin/java -cp hive-jackson/*:/Users/yangjie01/Tools/4.0/spark-4.0.0-SNAPSHOT-bin-3.4.0/conf/:/Users/yangjie01/Tools/4.0/spark-4.0.0-SNAPSHOT-bin-3.4.0/jars/slf4j-api-2.0.16.jar:/Users/yangjie01/Tools/4.0/spark-4.0.0-SNAPSHOT-bin-3.4.0/jars/* -Xmx1g -XX:+IgnoreUnrecognizedVMOptions --add-modules=jdk.incubator.vector --add-opens=java.base/java.lang=ALL-UNNAMED --add-opens=java.base/java.lang.invoke=ALL-UNNAMED --add-opens=java.base/java.lang.reflect=ALL-UNNAMED --add-opens=java.base/java.io=ALL-UNNAMED --add-opens=java.base/java.net=ALL-UNNAMED --add-opens=java.base/java.nio=ALL-UNNAMED --add-opens=java.base/java.util=ALL-UNNAMED --add-opens=java.base/java.util.concurrent=ALL-UNNAMED --add-opens=java.base/java.util.concurrent.atomic=ALL-UNNAMED --add-opens=java.base/jdk.internal.ref=ALL-UNNAMED --add-opens=java.base/sun.nio.ch=ALL-UNNAMED --add-opens=java.base/sun.nio.cs=ALL-UNNAMED --add-opens=java.base/sun.security.action=ALL-UNNAMED --add-opens=java.base/sun.util.calendar=ALL-UNNAMED --add-opens=java.security.jgss/sun.security.krb5=ALL-UNNAMED -Djdk.reflect.useDirectMethodHandle=false -Dio.netty.tryReflectionSetAccessible=true -Dderby.connection.requireAuthentication=false org.apache.spark.deploy.SparkSubmit --conf spark.log.structuredLogging.enabled=false --class org.apache.spark.sql.connect.service.SparkConnectServer --name Spark Connect server spark-internal
========================================
WARNING: Using incubator modules: jdk.incubator.vector
Using Spark's default log4j profile: org/apache/spark/log4j2-defaults.properties
{"ts":"2024-08-27T06:42:25.198Z","level":"WARN","msg":"Your hostname, MacBook-Pro.local, resolves to a loopback address: 127.0.0.1; using 172.22.200.254 instead (on interface en0)","context":{"host":"MacBook-Pro.local","host_port":"127.0.0.1","host_port2":"172.22.200.254","network_if":"en0"},"logger":"Utils"}
{"ts":"2024-08-27T06:42:25.199Z","level":"WARN","msg":"Set SPARK_LOCAL_IP if you need to bind to another address","logger":"Utils"}
{"ts":"2024-08-27T06:42:25.309Z","level":"INFO","msg":"Starting Spark session.","logger":"SparkConnectServer"}
{"ts":"2024-08-27T06:42:25.321Z","level":"INFO","msg":"Running Spark version 4.0.0-SNAPSHOT","logger":"SparkContext"}
{"ts":"2024-08-27T06:42:25.322Z","level":"INFO","msg":"OS info Mac OS X, 14.6.1, aarch64","logger":"SparkContext"}
{"ts":"2024-08-27T06:42:25.322Z","level":"INFO","msg":"Java version 17.0.12","logger":"SparkContext"}
{"ts":"2024-08-27T06:42:25.359Z","level":"WARN","msg":"Unable to load native-hadoop library for your platform... using builtin-java classes where applicable","logger":"NativeCodeLoader"}
{"ts":"2024-08-27T06:42:25.375Z","level":"INFO","msg":"==============================================================","logger":"ResourceUtils"}
{"ts":"2024-08-27T06:42:25.375Z","level":"INFO","msg":"No custom resources configured for spark.driver.","logger":"ResourceUtils"}
{"ts":"2024-08-27T06:42:25.375Z","level":"INFO","msg":"==============================================================","logger":"ResourceUtils"}
{"ts":"2024-08-27T06:42:25.376Z","level":"INFO","msg":"Submitted application: Spark Connect server","logger":"SparkContext"}
{"ts":"2024-08-27T06:42:25.383Z","level":"INFO","msg":"Default ResourceProfile created, executor resources: Map(cores -> name: cores, amount: 1, script: , vendor: , memory -> name: memory, amount: 1024, script: , vendor: , offHeap -> name: offHeap, amount: 0, script: , vendor: ), task resources: Map(cpus -> name: cpus, amount: 1.0)","logger":"ResourceProfile"}
{"ts":"2024-08-27T06:42:25.384Z","level":"INFO","msg":"Limiting resource is cpu","logger":"ResourceProfile"}
{"ts":"2024-08-27T06:42:25.384Z","level":"INFO","msg":"Added ResourceProfile id: 0","logger":"ResourceProfileManager"}
{"ts":"2024-08-27T06:42:25.400Z","level":"INFO","msg":"Changing view acls to: yangjie01","logger":"SecurityManager"}
{"ts":"2024-08-27T06:42:25.401Z","level":"INFO","msg":"Changing modify acls to: yangjie01","logger":"SecurityManager"}
{"ts":"2024-08-27T06:42:25.401Z","level":"INFO","msg":"Changing view acls groups to: yangjie01","logger":"SecurityManager"}
{"ts":"2024-08-27T06:42:25.401Z","level":"INFO","msg":"Changing modify acls groups to: yangjie01","logger":"SecurityManager"}
{"ts":"2024-08-27T06:42:25.402Z","level":"INFO","msg":"SecurityManager: authentication disabled; ui acls disabled; users with view permissions: yangjie01 groups with view permissions: EMPTY; users with modify permissions: yangjie01; groups with modify permissions: EMPTY; RPC SSL disabled","logger":"SecurityManager"}
{"ts":"2024-08-27T06:42:25.483Z","level":"INFO","msg":"Successfully started service 'sparkDriver' on port 51354.","logger":"Utils"}
{"ts":"2024-08-27T06:42:25.493Z","level":"INFO","msg":"Registering MapOutputTracker","logger":"SparkEnv"}
{"ts":"2024-08-27T06:42:25.496Z","level":"INFO","msg":"Registering BlockManagerMaster","logger":"SparkEnv"}
{"ts":"2024-08-27T06:42:25.503Z","level":"INFO","msg":"Using org.apache.spark.storage.DefaultTopologyMapper for getting topology information","logger":"BlockManagerMasterEndpoint"}
{"ts":"2024-08-27T06:42:25.503Z","level":"INFO","msg":"BlockManagerMasterEndpoint up","logger":"BlockManagerMasterEndpoint"}
{"ts":"2024-08-27T06:42:25.504Z","level":"INFO","msg":"Registering BlockManagerMasterHeartbeat","logger":"SparkEnv"}
{"ts":"2024-08-27T06:42:25.512Z","level":"INFO","msg":"Created local directory at /private/var/folders/j2/cfn7w6795538n_416_27rkqm0000gn/T/blockmgr-33631b4f-63ad-49a7-8285-f286ff242854","logger":"DiskBlockManager"}
{"ts":"2024-08-27T06:42:25.519Z","level":"INFO","msg":"Registering OutputCommitCoordinator","logger":"SparkEnv"}
{"ts":"2024-08-27T06:42:25.564Z","level":"INFO","msg":"Start Jetty 0.0.0.0:4040 for SparkUI","logger":"JettyUtils"}
{"ts":"2024-08-27T06:42:25.587Z","level":"INFO","msg":"Successfully started service 'SparkUI' on port 4040.","logger":"Utils"}
{"ts":"2024-08-27T06:42:25.608Z","level":"INFO","msg":"Changing view acls to: yangjie01","logger":"SecurityManager"}
{"ts":"2024-08-27T06:42:25.608Z","level":"INFO","msg":"Changing modify acls to: yangjie01","logger":"SecurityManager"}
{"ts":"2024-08-27T06:42:25.608Z","level":"INFO","msg":"Changing view acls groups to: yangjie01","logger":"SecurityManager"}
{"ts":"2024-08-27T06:42:25.608Z","level":"INFO","msg":"Changing modify acls groups to: yangjie01","logger":"SecurityManager"}
{"ts":"2024-08-27T06:42:25.608Z","level":"INFO","msg":"SecurityManager: authentication disabled; ui acls disabled; users with view permissions: yangjie01 groups with view permissions: EMPTY; users with modify permissions: yangjie01; groups with modify permissions: EMPTY; RPC SSL disabled","logger":"SecurityManager"}
{"ts":"2024-08-27T06:42:25.631Z","level":"INFO","msg":"Starting executor ID driver on host 172.22.200.254","logger":"Executor"}
{"ts":"2024-08-27T06:42:25.631Z","level":"INFO","msg":"OS info Mac OS X, 14.6.1, aarch64","logger":"Executor"}
{"ts":"2024-08-27T06:42:25.631Z","level":"INFO","msg":"Java version 17.0.12","logger":"Executor"}
{"ts":"2024-08-27T06:42:25.633Z","level":"INFO","msg":"Starting executor with user classpath (userClassPathFirst = false): ''","logger":"Executor"}
{"ts":"2024-08-27T06:42:25.634Z","level":"INFO","msg":"Created or updated repl class loader org.apache.spark.util.MutableURLClassLoader@6fff46bf for default.","logger":"Executor"}
{"ts":"2024-08-27T06:42:25.641Z","level":"INFO","msg":"Successfully started service 'org.apache.spark.network.netty.NettyBlockTransferService' on port 51355.","logger":"Utils"}
{"ts":"2024-08-27T06:42:25.643Z","level":"INFO","msg":"Server created on 172.22.200.254:51355","logger":"NettyBlockTransferService"}
{"ts":"2024-08-27T06:42:25.643Z","level":"INFO","msg":"Using org.apache.spark.storage.RandomBlockReplicationPolicy for block replication policy","logger":"BlockManager"}
{"ts":"2024-08-27T06:42:25.648Z","level":"INFO","msg":"Registering BlockManager BlockManagerId(driver, 172.22.200.254, 51355, None)","logger":"BlockManagerMaster"}
{"ts":"2024-08-27T06:42:25.650Z","level":"INFO","msg":"Registering block manager 172.22.200.254:51355 with 434.4 MiB RAM, BlockManagerId(driver, 172.22.200.254, 51355, None)","logger":"BlockManagerMasterEndpoint"}
{"ts":"2024-08-27T06:42:25.651Z","level":"INFO","msg":"Registered BlockManager BlockManagerId(driver, 172.22.200.254, 51355, None)","logger":"BlockManagerMaster"}
{"ts":"2024-08-27T06:42:25.651Z","level":"INFO","msg":"Initialized BlockManager: BlockManagerId(driver, 172.22.200.254, 51355, None)","logger":"BlockManager"}
{"ts":"2024-08-27T06:42:25.793Z","level":"INFO","msg":"Successfully started service 'org.apache.spark.sql.connect.service.SparkConnectService$' on port 15002.","logger":"Utils"}
{"ts":"2024-08-27T06:42:25.798Z","level":"INFO","msg":"Spark Connect server started at: 0:0:0:0:0:0:0:0:15002","logger":"SparkConnectServer"}

LuciferYang avatar Aug 27 '24 06:08 LuciferYang 

sbin/start-connect-server.sh --conf spark.log.structuredLogging.enabled=false

I used the command dev/make-distribution.sh --tgz -Phive to package the latest code.

And without this pr, I manually run sbin/start-connect-server.sh --conf spark.log.structuredLogging.enabled=false, and it did use structuredLogging, even though spark.log.structuredLogging.enabled was specified as false:

tail -100f logs/spark-yangjie01-org.apache.spark.sql.connect.service.SparkConnectServer-1-MacBook-Pro.local.out

Spark Command: /Users/yangjie01/Tools/zulu17/bin/java -cp hive-jackson/*:/Users/yangjie01/Tools/4.0/spark-4.0.0-SNAPSHOT-bin-3.4.0/conf/:/Users/yangjie01/Tools/4.0/spark-4.0.0-SNAPSHOT-bin-3.4.0/jars/slf4j-api-2.0.16.jar:/Users/yangjie01/Tools/4.0/spark-4.0.0-SNAPSHOT-bin-3.4.0/jars/* -Xmx1g -XX:+IgnoreUnrecognizedVMOptions --add-modules=jdk.incubator.vector --add-opens=java.base/java.lang=ALL-UNNAMED --add-opens=java.base/java.lang.invoke=ALL-UNNAMED --add-opens=java.base/java.lang.reflect=ALL-UNNAMED --add-opens=java.base/java.io=ALL-UNNAMED --add-opens=java.base/java.net=ALL-UNNAMED --add-opens=java.base/java.nio=ALL-UNNAMED --add-opens=java.base/java.util=ALL-UNNAMED --add-opens=java.base/java.util.concurrent=ALL-UNNAMED --add-opens=java.base/java.util.concurrent.atomic=ALL-UNNAMED --add-opens=java.base/jdk.internal.ref=ALL-UNNAMED --add-opens=java.base/sun.nio.ch=ALL-UNNAMED --add-opens=java.base/sun.nio.cs=ALL-UNNAMED --add-opens=java.base/sun.security.action=ALL-UNNAMED --add-opens=java.base/sun.util.calendar=ALL-UNNAMED --add-opens=java.security.jgss/sun.security.krb5=ALL-UNNAMED -Djdk.reflect.useDirectMethodHandle=false -Dio.netty.tryReflectionSetAccessible=true -Dderby.connection.requireAuthentication=false org.apache.spark.deploy.SparkSubmit --conf spark.log.structuredLogging.enabled=false --class org.apache.spark.sql.connect.service.SparkConnectServer --name Spark Connect server spark-internal
========================================
WARNING: Using incubator modules: jdk.incubator.vector
Using Spark's default log4j profile: org/apache/spark/log4j2-defaults.properties
{"ts":"2024-08-27T06:42:25.198Z","level":"WARN","msg":"Your hostname, MacBook-Pro.local, resolves to a loopback address: 127.0.0.1; using 172.22.200.254 instead (on interface en0)","context":{"host":"MacBook-Pro.local","host_port":"127.0.0.1","host_port2":"172.22.200.254","network_if":"en0"},"logger":"Utils"}
{"ts":"2024-08-27T06:42:25.199Z","level":"WARN","msg":"Set SPARK_LOCAL_IP if you need to bind to another address","logger":"Utils"}
{"ts":"2024-08-27T06:42:25.309Z","level":"INFO","msg":"Starting Spark session.","logger":"SparkConnectServer"}
{"ts":"2024-08-27T06:42:25.321Z","level":"INFO","msg":"Running Spark version 4.0.0-SNAPSHOT","logger":"SparkContext"}
{"ts":"2024-08-27T06:42:25.322Z","level":"INFO","msg":"OS info Mac OS X, 14.6.1, aarch64","logger":"SparkContext"}
{"ts":"2024-08-27T06:42:25.322Z","level":"INFO","msg":"Java version 17.0.12","logger":"SparkContext"}
{"ts":"2024-08-27T06:42:25.359Z","level":"WARN","msg":"Unable to load native-hadoop library for your platform... using builtin-java classes where applicable","logger":"NativeCodeLoader"}
{"ts":"2024-08-27T06:42:25.375Z","level":"INFO","msg":"==============================================================","logger":"ResourceUtils"}
{"ts":"2024-08-27T06:42:25.375Z","level":"INFO","msg":"No custom resources configured for spark.driver.","logger":"ResourceUtils"}
{"ts":"2024-08-27T06:42:25.375Z","level":"INFO","msg":"==============================================================","logger":"ResourceUtils"}
{"ts":"2024-08-27T06:42:25.376Z","level":"INFO","msg":"Submitted application: Spark Connect server","logger":"SparkContext"}
{"ts":"2024-08-27T06:42:25.383Z","level":"INFO","msg":"Default ResourceProfile created, executor resources: Map(cores -> name: cores, amount: 1, script: , vendor: , memory -> name: memory, amount: 1024, script: , vendor: , offHeap -> name: offHeap, amount: 0, script: , vendor: ), task resources: Map(cpus -> name: cpus, amount: 1.0)","logger":"ResourceProfile"}
{"ts":"2024-08-27T06:42:25.384Z","level":"INFO","msg":"Limiting resource is cpu","logger":"ResourceProfile"}
{"ts":"2024-08-27T06:42:25.384Z","level":"INFO","msg":"Added ResourceProfile id: 0","logger":"ResourceProfileManager"}
{"ts":"2024-08-27T06:42:25.400Z","level":"INFO","msg":"Changing view acls to: yangjie01","logger":"SecurityManager"}
{"ts":"2024-08-27T06:42:25.401Z","level":"INFO","msg":"Changing modify acls to: yangjie01","logger":"SecurityManager"}
{"ts":"2024-08-27T06:42:25.401Z","level":"INFO","msg":"Changing view acls groups to: yangjie01","logger":"SecurityManager"}
{"ts":"2024-08-27T06:42:25.401Z","level":"INFO","msg":"Changing modify acls groups to: yangjie01","logger":"SecurityManager"}
{"ts":"2024-08-27T06:42:25.402Z","level":"INFO","msg":"SecurityManager: authentication disabled; ui acls disabled; users with view permissions: yangjie01 groups with view permissions: EMPTY; users with modify permissions: yangjie01; groups with modify permissions: EMPTY; RPC SSL disabled","logger":"SecurityManager"}
{"ts":"2024-08-27T06:42:25.483Z","level":"INFO","msg":"Successfully started service 'sparkDriver' on port 51354.","logger":"Utils"}
{"ts":"2024-08-27T06:42:25.493Z","level":"INFO","msg":"Registering MapOutputTracker","logger":"SparkEnv"}
{"ts":"2024-08-27T06:42:25.496Z","level":"INFO","msg":"Registering BlockManagerMaster","logger":"SparkEnv"}
{"ts":"2024-08-27T06:42:25.503Z","level":"INFO","msg":"Using org.apache.spark.storage.DefaultTopologyMapper for getting topology information","logger":"BlockManagerMasterEndpoint"}
{"ts":"2024-08-27T06:42:25.503Z","level":"INFO","msg":"BlockManagerMasterEndpoint up","logger":"BlockManagerMasterEndpoint"}
{"ts":"2024-08-27T06:42:25.504Z","level":"INFO","msg":"Registering BlockManagerMasterHeartbeat","logger":"SparkEnv"}
{"ts":"2024-08-27T06:42:25.512Z","level":"INFO","msg":"Created local directory at /private/var/folders/j2/cfn7w6795538n_416_27rkqm0000gn/T/blockmgr-33631b4f-63ad-49a7-8285-f286ff242854","logger":"DiskBlockManager"}
{"ts":"2024-08-27T06:42:25.519Z","level":"INFO","msg":"Registering OutputCommitCoordinator","logger":"SparkEnv"}
{"ts":"2024-08-27T06:42:25.564Z","level":"INFO","msg":"Start Jetty 0.0.0.0:4040 for SparkUI","logger":"JettyUtils"}
{"ts":"2024-08-27T06:42:25.587Z","level":"INFO","msg":"Successfully started service 'SparkUI' on port 4040.","logger":"Utils"}
{"ts":"2024-08-27T06:42:25.608Z","level":"INFO","msg":"Changing view acls to: yangjie01","logger":"SecurityManager"}
{"ts":"2024-08-27T06:42:25.608Z","level":"INFO","msg":"Changing modify acls to: yangjie01","logger":"SecurityManager"}
{"ts":"2024-08-27T06:42:25.608Z","level":"INFO","msg":"Changing view acls groups to: yangjie01","logger":"SecurityManager"}
{"ts":"2024-08-27T06:42:25.608Z","level":"INFO","msg":"Changing modify acls groups to: yangjie01","logger":"SecurityManager"}
{"ts":"2024-08-27T06:42:25.608Z","level":"INFO","msg":"SecurityManager: authentication disabled; ui acls disabled; users with view permissions: yangjie01 groups with view permissions: EMPTY; users with modify permissions: yangjie01; groups with modify permissions: EMPTY; RPC SSL disabled","logger":"SecurityManager"}
{"ts":"2024-08-27T06:42:25.631Z","level":"INFO","msg":"Starting executor ID driver on host 172.22.200.254","logger":"Executor"}
{"ts":"2024-08-27T06:42:25.631Z","level":"INFO","msg":"OS info Mac OS X, 14.6.1, aarch64","logger":"Executor"}
{"ts":"2024-08-27T06:42:25.631Z","level":"INFO","msg":"Java version 17.0.12","logger":"Executor"}
{"ts":"2024-08-27T06:42:25.633Z","level":"INFO","msg":"Starting executor with user classpath (userClassPathFirst = false): ''","logger":"Executor"}
{"ts":"2024-08-27T06:42:25.634Z","level":"INFO","msg":"Created or updated repl class loader org.apache.spark.util.MutableURLClassLoader@6fff46bf for default.","logger":"Executor"}
{"ts":"2024-08-27T06:42:25.641Z","level":"INFO","msg":"Successfully started service 'org.apache.spark.network.netty.NettyBlockTransferService' on port 51355.","logger":"Utils"}
{"ts":"2024-08-27T06:42:25.643Z","level":"INFO","msg":"Server created on 172.22.200.254:51355","logger":"NettyBlockTransferService"}
{"ts":"2024-08-27T06:42:25.643Z","level":"INFO","msg":"Using org.apache.spark.storage.RandomBlockReplicationPolicy for block replication policy","logger":"BlockManager"}
{"ts":"2024-08-27T06:42:25.648Z","level":"INFO","msg":"Registering BlockManager BlockManagerId(driver, 172.22.200.254, 51355, None)","logger":"BlockManagerMaster"}
{"ts":"2024-08-27T06:42:25.650Z","level":"INFO","msg":"Registering block manager 172.22.200.254:51355 with 434.4 MiB RAM, BlockManagerId(driver, 172.22.200.254, 51355, None)","logger":"BlockManagerMasterEndpoint"}
{"ts":"2024-08-27T06:42:25.651Z","level":"INFO","msg":"Registered BlockManager BlockManagerId(driver, 172.22.200.254, 51355, None)","logger":"BlockManagerMaster"}
{"ts":"2024-08-27T06:42:25.651Z","level":"INFO","msg":"Initialized BlockManager: BlockManagerId(driver, 172.22.200.254, 51355, None)","logger":"BlockManager"}
{"ts":"2024-08-27T06:42:25.793Z","level":"INFO","msg":"Successfully started service 'org.apache.spark.sql.connect.service.SparkConnectService$' on port 15002.","logger":"Utils"}
{"ts":"2024-08-27T06:42:25.798Z","level":"INFO","msg":"Spark Connect server started at: 0:0:0:0:0:0:0:0:15002","logger":"SparkConnectServer"}

After packaging, I didn't perform any other actions before executing sbin/start-connect-server.sh --conf spark.log.structuredLogging.enabled=false, except for unpacking the tarball

My Testing environment:

macos: 14.6.1 (23G93)
Java: openjdk version "17.0.12" 2024-07-16 LTS

cc @panbingkun @wayneguow do you have time to help check this issue? Thanks ~ I'm not sure if it's related to some environmental characteristics.

LuciferYang avatar Aug 27 '24 06:08 LuciferYang

When there is no configuration (eg: log4j2.properties) in conf, the above issue will be triggered; If there is, then this issue does not exist.

rootLogger.level = debug

panbingkun avatar Aug 27 '24 07:08 panbingkun

https://github.com/apache/spark/pull/47500#issuecomment-2311482962 https://github.com/apache/spark/pull/47500#issuecomment-2311595579

The difference between these two log is that the log of @pan3793 has one additional line of Using Spark's default log4j profile: org/apache/spark/log4j2-defaults.properties, and then it uses structuredLogging for printing, more like an issue caused by a classpath ...although I have not yet found the root cause.

LuciferYang avatar Aug 27 '24 08:08 LuciferYang

I still can't reproduce this one latest master branch. I will try on a different laptop and get back here today.

Update: I tried on another laptop and still can't reproduce the issue.

@pan3793 @LuciferYang @panbingkun Are you using the latest master branch?

gengliangwang avatar Aug 27 '24 18:08 gengliangwang

I still can't reproduce this one latest master branch. I will try on a different laptop and get back here today.

Update: I tried on another laptop and still can't reproduce the issue.

@pan3793 @LuciferYang @panbingkun Are you using the latest master branch?

Yes, I conducted the test on August 27th. The revision recorded in the spark-version-info.properties file of the packaged Spark client is 9fc1e05224d2b4207885a1d4f822fed6db0cb1a1, which corresponds to commit

commit 9fc1e05224d2b4207885a1d4f822fed6db0cb1a1
Author: Hyukjin Kwon <[email protected]>
Date:   Tue Aug 27 14:51:02 2024 +0900

    [SPARK-49402][PYTHON] Fix Binder integration in PySpark documentation

This was relatively new code on August 27th.

LuciferYang avatar Aug 29 '24 05:08 LuciferYang

These days I have some other things to do. I will investigate why some environments load org/apache/spark/log4j2-defaults.properties at the weekend, if there is no further conclusion before that.

LuciferYang avatar Aug 29 '24 07:08 LuciferYang

Are you using the latest master branch?

@gengliangwang yes

... verified the latest master branch https://github.com/apache/spark/commit/d64d1f76ff28f97db0ad3f3647ae2683e80095a2

@LuciferYang thanks for the help!

pan3793 avatar Aug 29 '24 07:08 pan3793

In the scenario described by the current PR, I believe the issue is real:

  1. The initialization of the org.apache.spark.internal.config object precedes the actual effectiveness of the --conf spark.log.structuredLogging.enabled=false option from the command line. The former is initialized in org.apache.spark.deploy.SparkSubmitArguments#loadEnvironmentArguments, while the latter waits until org.apache.spark.deploy.SparkSubmit#doSubmit to execute Logging.enableStructuredLogging() or Logging.disableStructuredLogging().

  2. The org.apache.spark.internal.config object triggers the invocation of the Utils.localCanonicalHostName() method during initialization.

https://github.com/apache/spark/blob/0602020eb3b346a8c50ad32eeda4e6dabb70c584/core/src/main/scala/org/apache/spark/internal/config/package.scala#L1149-L1153

  1. If the environment variable SPARK_LOCAL_HOSTNAME is not set, the Utils.localCanonicalHostName() method will call org.apache.spark.util.Utils#findLocalInetAddress to initialize org.apache.spark.util.Utils#localIpAddress.

https://github.com/apache/spark/blob/0602020eb3b346a8c50ad32eeda4e6dabb70c584/core/src/main/scala/org/apache/spark/util/Utils.scala#L927-L929

https://github.com/apache/spark/blob/0602020eb3b346a8c50ad32eeda4e6dabb70c584/core/src/main/scala/org/apache/spark/util/Utils.scala#L913

https://github.com/apache/spark/blob/0602020eb3b346a8c50ad32eeda4e6dabb70c584/core/src/main/scala/org/apache/spark/util/Utils.scala#L871

  1. In the findLocalInetAddress() method, if the environment variable SPARK_LOCAL_IP is set, the issue described in the current PR will not occur.

  2. Otherwise, if InetAddress.getLocalHost can obtain the actual IP of the current host instead of 127.0.0.1, the issue described in the current PR will also not occur.

  3. When the return value of InetAddress.getLocalHost is 127.0.0.1, it triggers additional calculations to obtain the actual physical machine IP. At this time, it triggers log printing. However, since Logging.enableStructuredLogging() or Logging.disableStructuredLogging() has not been called based on spark.log.structuredLogging.enabled at this point, org.apache.spark.internal.Logging#isStructuredLoggingEnabled will return the default value, which is true. Therefore, it will load org/apache/spark/log4j2-defaults.properties to use StructuredLogging.

https://github.com/apache/spark/blob/0602020eb3b346a8c50ad32eeda4e6dabb70c584/core/src/main/scala/org/apache/spark/util/Utils.scala#L873-L911

A possible solution I can think of is to change org.apache.spark.internal.config#DRIVER_HOST_ADDRESS and org.apache.spark.internal.config#DRIVER_BIND_ADDRESS from val to lazy val. This can avoid the aforementioned unexpected early initialization. I manually tested this solution, and it can restore the logs to normal. However, whether this will cause other side effects, I am currently unable to determine.

Could you help confirm whether InetAddress.getLocalHost returns the actual IP address instead of 127.0.0.1 in your testing environment? @HyukjinKwon @gengliangwang @wayneguow

Also, do you have any other ideas for fixing this issue? @HyukjinKwon @gengliangwang @pan3793 @panbingkun @wayneguow

LuciferYang avatar Aug 30 '24 08:08 LuciferYang

I guess besides the above scenario, there may be other scenarios that triggered this loading in advance.

panbingkun avatar Aug 30 '24 08:08 panbingkun

I still can't reproduce this one latest master branch. I will try on a different laptop and get back here today.

Update: I tried on another laptop and still can't reproduce the issue.

@pan3793 @LuciferYang @panbingkun Are you using the latest master branch?

Yes.

panbingkun avatar Aug 30 '24 08:08 panbingkun

@LuciferYang Thanks for digging out this issue.

change ... from val to lazy val. This can avoid the aforementioned unexpected early initialization.

IMO we can not forbid logging system early initialization thoroughly, the approach proposed in this PR to reconfigure logging after applying spark.log.structuredLogging.enabled makes more sense.

pan3793 avatar Aug 30 '24 09:08 pan3793

@LuciferYang Thanks for digging out this issue.

change ... from val to lazy val. This can avoid the aforementioned unexpected early initialization.

IMO we can not forbid logging system early initialization thoroughly, the approach proposed in this PR to reconfigure logging after applying spark.log.structuredLogging.enabled makes more sense.

fine to me.

LuciferYang avatar Aug 30 '24 09:08 LuciferYang

@LuciferYang Thanks a lot for the investigation!

I verified that your assumption is true

> InetAddress.getLocalHost
val res0: java.net.InetAddress = hostname/192.168.1.96

gengliangwang avatar Sep 01 '24 04:09 gengliangwang

Thanks, merging to master

gengliangwang avatar Sep 01 '24 04:09 gengliangwang